From a5b3989e5db0a3b22e44b84412227a8e487bcef2 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Thu, 20 Sep 2012 23:18:19 +0100 Subject: [PATCH] Insert a new log level 4 for HTTP IN and HTTP OUT that will log how long the request took. This is only printed if debug http level >= 4 and the request didn't take more than the time considered 'long', in which case the existing log message is printed. This displaces the previous log levels 4 and 5 which are now 5 and 6 respectively. --- .../Servers/HttpServer/BaseHttpServer.cs | 47 ++++++++++++------ OpenSim/Framework/Servers/MainServer.cs | 48 ++++++++++++------- OpenSim/Framework/WebUtil.cs | 24 ++++++++++ 3 files changed, 87 insertions(+), 32 deletions(-) diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs index f93b3dd778..4e04dd892a 100644 --- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs +++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs @@ -54,6 +54,12 @@ namespace OpenSim.Framework.Servers.HttpServer private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); private HttpServerLogWriter httpserverlog = new HttpServerLogWriter(); + /// + /// Gets or sets the debug level. + /// + /// + /// See MainServer.DebugLevel. + /// public int DebugLevel { get; set; } private volatile int NotSocketErrors = 0; @@ -529,8 +535,8 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); buffer = HandleHTTPRequest(request, response); break; @@ -541,8 +547,8 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); buffer = HandleLLSDRequests(request, response); break; @@ -640,7 +646,18 @@ namespace OpenSim.Framework.Servers.HttpServer uriString, requestHandler != null ? requestHandler.Name : "", requestHandler != null ? requestHandler.Description : "", - request.RemoteIPEndPoint.ToString(), + request.RemoteIPEndPoint, + tickdiff); + } + else if (DebugLevel >= 4) + { + m_log.DebugFormat( + "[BASE HTTP SERVER]: HTTP IN {0} {1} {2} {3} from {4} took {5}ms", + requestMethod, + uriString, + requestHandler != null ? requestHandler.Name : "", + requestHandler != null ? requestHandler.Description : "", + request.RemoteIPEndPoint, tickdiff); } } @@ -649,30 +666,30 @@ namespace OpenSim.Framework.Servers.HttpServer private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3}", - request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description); + "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3} from {4}", + request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } private void LogIncomingToContentTypeHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } private void LogIncomingToXmlRpcHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1}", - request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1} from {2}", + request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } @@ -682,7 +699,7 @@ namespace OpenSim.Framework.Servers.HttpServer { string output; - if (DebugLevel == 4) + if (DebugLevel == 5) { const int sampleLength = 80; char[] sampleChars = new char[sampleLength]; diff --git a/OpenSim/Framework/Servers/MainServer.cs b/OpenSim/Framework/Servers/MainServer.cs index b7a133e5c4..72f9cce31b 100644 --- a/OpenSim/Framework/Servers/MainServer.cs +++ b/OpenSim/Framework/Servers/MainServer.cs @@ -51,8 +51,9 @@ namespace OpenSim.Framework.Servers /// If DebugLevel >= 1 then short warnings are logged when receiving bad input data. /// If DebugLevel >= 2 then long warnings are logged when receiving bad input data. /// If DebugLevel >= 3 then short notices about all incoming non-poll HTTP requests are logged. - /// If DebugLevel >= 4 then the start of the body of incoming non-poll HTTP requests will be logged. - /// If DebugLevel >= 5 then the entire body of incoming non-poll HTTP requests will be logged. + /// If DebugLevel >= 4 then the time taken to fulfill the request is logged. + /// If DebugLevel >= 5 then the start of the body of incoming non-poll HTTP requests will be logged. + /// If DebugLevel >= 6 then the entire body of incoming non-poll HTTP requests will be logged. /// public static int DebugLevel { @@ -115,15 +116,17 @@ namespace OpenSim.Framework.Servers "Debug", false, "debug http", "debug http []", "Turn on http request logging.", "If in or all and\n" - + " level <= 0, then no extra logging is done.\n" - + " level >= 1, then short warnings are logged when receiving bad input data.\n" - + " level >= 2, then long warnings are logged when receiving bad input data.\n" - + " level >= 3, then short notices about all incoming non-poll HTTP requests are logged.\n" - + " level >= 4, then a sample from the beginning of the incoming data is logged.\n" - + " level >= 5, then the entire incoming data is logged.\n" + + " level <= 0 then no extra logging is done.\n" + + " level >= 1 then short warnings are logged when receiving bad input data.\n" + + " level >= 2 then long warnings are logged when receiving bad input data.\n" + + " level >= 3 then short notices about all incoming non-poll HTTP requests are logged.\n" + + " level >= 4 then the time taken to fulfill the request is logged.\n" + + " level >= 5 then a sample from the beginning of the incoming data is logged.\n" + + " level >= 6 then the entire incoming data is logged.\n" + " no level is specified then the current level is returned.\n\n" + "If out or all and\n" - + " level >= 3. then short notices about all outgoing requests going through WebUtil are logged.\n", + + " level >= 3 then short notices about all outgoing requests going through WebUtil are logged.\n" + + " level >= 4 then the time taken to fulfill the request is logged.\n", HandleDebugHttpCommand); } @@ -135,7 +138,7 @@ namespace OpenSim.Framework.Servers { if (cmdparams.Length < 3) { - MainConsole.Instance.Output("Usage: debug http 0..5"); + MainConsole.Instance.Output("Usage: debug http 0..6"); return; } @@ -145,12 +148,23 @@ namespace OpenSim.Framework.Servers string subCommand = cmdparams[2]; - if (subCommand == "in") + if (subCommand.ToLower() == "in") + { inReqs = true; - else if (subCommand == "out") + } + else if (subCommand.ToLower() == "out") + { outReqs = true; - else + } + else if (subCommand.ToLower() == "all") + { allReqs = true; + } + else + { + MainConsole.Instance.Output("You must specify in, out or all"); + return; + } if (cmdparams.Length >= 4) { @@ -172,22 +186,22 @@ namespace OpenSim.Framework.Servers if (allReqs || inReqs) { MainServer.DebugLevel = newDebug; - MainConsole.Instance.OutputFormat("In debug level set to {0}", newDebug); + MainConsole.Instance.OutputFormat("IN debug level set to {0}", newDebug); } if (allReqs || outReqs) { WebUtil.DebugLevel = newDebug; - MainConsole.Instance.OutputFormat("Out debug level set to {0}", newDebug); + MainConsole.Instance.OutputFormat("OUT debug level set to {0}", newDebug); } } else { if (allReqs || inReqs) - MainConsole.Instance.OutputFormat("Current in debug level is {0}", MainServer.DebugLevel); + MainConsole.Instance.OutputFormat("Current IN debug level is {0}", MainServer.DebugLevel); if (allReqs || outReqs) - MainConsole.Instance.OutputFormat("Current out debug level is {0}", WebUtil.DebugLevel); + MainConsole.Instance.OutputFormat("Current OUT debug level is {0}", WebUtil.DebugLevel); } } diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs index 7c4e852591..64d61f1aa0 100644 --- a/OpenSim/Framework/WebUtil.cs +++ b/OpenSim/Framework/WebUtil.cs @@ -250,6 +250,10 @@ namespace OpenSim.Framework strBuffer != null ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer) : ""); + else if (DebugLevel >= 4) + m_log.DebugFormat( + "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", + reqnum, tickdiff, tickdata); } m_log.DebugFormat( @@ -405,6 +409,10 @@ namespace OpenSim.Framework queryString != null ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString : ""); + else if (DebugLevel >= 4) + m_log.DebugFormat( + "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", + reqnum, tickdiff, tickdata); } m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage); @@ -879,6 +887,12 @@ namespace OpenSim.Framework tickdata, originalRequest); } + else if (WebUtil.DebugLevel >= 4) + { + m_log.DebugFormat( + "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", + reqnum, tickdiff, tickdata); + } } } @@ -995,6 +1009,10 @@ namespace OpenSim.Framework tickdiff, tickdata, obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj); + else if (WebUtil.DebugLevel >= 4) + m_log.DebugFormat( + "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", + reqnum, tickdiff, tickdata); return respstring; } @@ -1144,6 +1162,12 @@ namespace OpenSim.Framework tickdata, originalRequest); } + else if (WebUtil.DebugLevel >= 4) + { + m_log.DebugFormat( + "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", + reqnum, tickdiff, tickdata); + } return deserial; }