3 files changed, 168 insertions, 45 deletions

diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
index 43a19fa..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]: Found a {0} content type handler for {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]: Found a {0} content type handler for {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]: Found stream handler for {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]: Found a {0} content type handler for {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]: Assuming a generic XMLRPC request for {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 7402c73..72f9cce 100644
--- a/OpenSim/Framework/Servers/MainServer.cs
+++ b/OpenSim/Framework/Servers/MainServer.cs
@@ -48,9 +48,12 @@ namespace OpenSim.Framework.Servers
         /// Control the printing of certain debug messages.
         /// </summary>
         /// <remarks>
-        /// 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 >= 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 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
         {
@@ -102,7 +105,6 @@ namespace OpenSim.Framework.Servers
             get { return new Dictionary<uint, BaseHttpServer>(m_Servers); }
         }
 
-
         public static void RegisterHttpConsoleCommands(ICommandConsole console)
         {
             console.Commands.AddCommand(
@@ -111,15 +113,20 @@ namespace OpenSim.Framework.Servers
                 "Show all registered http handlers", HandleShowHttpHandlersCommand);
 
             console.Commands.AddCommand(
-                "Debug", false, "debug http", "debug http [<level>]",
-                "Turn on inbound non-poll http request debugging.",
-                  "If level <= 0, then no extra logging is done.\n"
-                + "If level >= 1, then short warnings are logged when receiving bad input data.\n"
-                + "If level >= 2, then long warnings are logged when receiving bad input data.\n"
-                + "If level >= 3, then short notices about all incoming non-poll HTTP requests are logged.\n"
-                + "If level >= 4, then a sample from the beginning of the incoming data is logged.\n"
-                + "If level >= 5, then the entire incoming data is logged.\n"
-                + "If no level is specified then the current level is returned.",
+                "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 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 >= 4 then the time taken to fulfill the request is logged.\n",
                 HandleDebugHttpCommand);
         }
 
@@ -127,24 +134,74 @@ namespace OpenSim.Framework.Servers
         /// Turn on some debugging values for OpenSim.
         /// </summary>
         /// <param name="args"></param>
-        private static void HandleDebugHttpCommand(string module, string[] args)
+        private static void HandleDebugHttpCommand(string module, string[] cmdparams)
         {
-            if (args.Length == 3)
+            if (cmdparams.Length < 3)
+            {
+                MainConsole.Instance.Output("Usage: debug http <in|out|all> 0..6");
+                return;
+            }
+
+            bool inReqs = false;
+            bool outReqs = false;
+            bool allReqs = false;
+
+            string subCommand = cmdparams[2];
+
+            if (subCommand.ToLower() == "in")
+            {
+                inReqs = true;
+            }
+            else if (subCommand.ToLower() == "out")
+            {
+                outReqs = true;
+            }
+            else if (subCommand.ToLower() == "all")
+            {
+                allReqs = true;
+            }
+            else
             {
+                MainConsole.Instance.Output("You must specify in, out or all");
+                return;
+            }
+
+            if (cmdparams.Length >= 4)
+            {
+                string rawNewDebug = cmdparams[3];
                 int newDebug;
-                if (int.TryParse(args[2], out newDebug))
+
+                if (!int.TryParse(rawNewDebug, out newDebug))
+                {
+                    MainConsole.Instance.OutputFormat("{0} is not a valid debug level", rawNewDebug);
+                    return;
+                }
+
+                if (newDebug < 0 || newDebug > 5)
+                {
+                    MainConsole.Instance.OutputFormat("{0} is outside the valid debug level range of 0..5", newDebug);
+                    return;
+                }
+
+                if (allReqs || inReqs)
                 {
                     MainServer.DebugLevel = newDebug;
-                    MainConsole.Instance.OutputFormat("Debug http 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);
                 }
-            }
-            else if (args.Length == 2)
-            {
-                MainConsole.Instance.OutputFormat("Current debug http level is {0}", MainServer.DebugLevel);
             }
             else
             {
-                MainConsole.Instance.Output("Usage: debug http 0..5");
+                if (allReqs || inReqs)
+                    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);
             }
         }
 
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index 2aa4af5..64d61f1 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -54,6 +54,14 @@ namespace OpenSim.Framework
                 MethodBase.GetCurrentMethod().DeclaringType);
 
         /// <summary>
+        /// Control the printing of certain debug messages.
+        /// </summary>
+        /// <remarks>
+        /// If DebugLevel >= 3 then short notices about outgoing HTTP requests are logged.
+        /// </remarks>
+        public static int DebugLevel { get; set; }
+
+        /// <summary>
         /// Request number for diagnostic purposes.
         /// </summary>
         public static int RequestNumber = 0;
@@ -146,7 +154,11 @@ namespace OpenSim.Framework
         private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
         {
             int reqnum = RequestNumber++;
-            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+            if (DebugLevel >= 3)
+                m_log.DebugFormat(
+                    "[WEB UTIL]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})",
+                    reqnum, method, url, timeout, compressed);
 
             string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
@@ -238,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(
@@ -317,7 +333,11 @@ namespace OpenSim.Framework
         {
             int reqnum = RequestNumber++;
             string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown";
-            // m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
+
+            if (DebugLevel >= 3)
+                m_log.DebugFormat(
+                    "[WEB UTIL]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})",
+                    reqnum, method, url, timeout);
             
             string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
@@ -389,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);
@@ -643,7 +667,6 @@ namespace OpenSim.Framework
         /// <returns></returns>
         public static string[] GetPreferredImageTypes(string accept)
         {
-
             if (accept == null || accept == string.Empty)
                 return new string[0];
 
@@ -695,13 +718,15 @@ namespace OpenSim.Framework
                 string requestUrl, TRequest obj, Action<TResponse> action)
         {
             int reqnum = WebUtil.RequestNumber++;
-            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+            if (WebUtil.DebugLevel >= 3)
+                m_log.DebugFormat(
+                    "[WEB UTIL]: HTTP OUT {0} AsynchronousRequestObject {1} {2}",
+                    reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
             int tickdata = 0;
 
-            //            m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} {1}", verb, requestUrl);
-
             Type type = typeof(TRequest);
 
             WebRequest request = WebRequest.Create(requestUrl);
@@ -862,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);
+            }
         }
     }
 
@@ -882,7 +913,11 @@ namespace OpenSim.Framework
         public static string MakeRequest(string verb, string requestUrl, string obj)
         {
             int reqnum = WebUtil.RequestNumber++;
-            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+            if (WebUtil.DebugLevel >= 3)
+                m_log.DebugFormat(
+                    "[WEB UTIL]: HTTP OUT {0} SynchronousRestForms {1} {2}",
+                    reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
             int tickdata = 0;
@@ -974,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;
         }
@@ -998,7 +1037,11 @@ namespace OpenSim.Framework
         public static TResponse MakeRequest<TRequest, TResponse>(string verb, string requestUrl, TRequest obj)
         {
             int reqnum = WebUtil.RequestNumber++;
-            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+            if (WebUtil.DebugLevel >= 3)
+                m_log.DebugFormat(
+                    "[WEB UTIL]: HTTP OUT {0} SynchronousRestObject {1} {2}",
+                    reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
             int tickdata = 0;
@@ -1119,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;
         }