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.

3 files changed, 87 insertions, 32 deletions

diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
index f93b3dd..4e04dd8 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();
 
+        /// <summary>
+        /// Gets or sets the debug level.
+        /// </summary>
+        /// <value>
+        /// See MainServer.DebugLevel.
+        /// </value>
         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 b7a133e..72f9cce 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.
         /// </remarks>
         public static int DebugLevel
         {
@@ -115,15 +116,17 @@ namespace OpenSim.Framework.Servers
                 "Debug", false, "debug http", "debug http <in|out|all> [<level>]",
                 "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 <in|out|all> 0..5");
+                MainConsole.Instance.Output("Usage: debug http <in|out|all> 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 7c4e852..64d61f1 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;
         }