Improved logging of HTTP requests

- MemoryBuffer isn't seekable, so we can't log it. Log the string instead.
- Handle compressed streams
- Don't attempt to dump binary data. Either don't log it at all (if we know it's binary), or at least convert non-ASCII characters to ASCII.
- Log responses to HTTP requests
- Use the same log prefix for all of these log messages ("[LOGHTTP]"), to make them easy to see at a glance
- Increased the snippet length to 200 (80 doesn't show enough), and add "..." only if the message was actually truncated

Resolves http://opensimulator.org/mantis/view.php?id=6949

OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs

@@ -46,6 +46,7 @@ using CoolHTTPListener = HttpServer.HttpListener;
 using HttpListener=System.Net.HttpListener;
 using LogPrio=HttpServer.LogPrio;
 using OpenSim.Framework.Monitoring;
+using System.IO.Compression;
 
 namespace OpenSim.Framework.Servers.HttpServer
 {
@@ -690,6 +691,23 @@ namespace OpenSim.Framework.Servers.HttpServer
 
                 if (buffer != null)
                 {
+                    if (WebUtil.DebugLevel >= 5)
+                    {
+                        string output = System.Text.Encoding.UTF8.GetString(buffer);
+
+                        if (WebUtil.DebugLevel >= 6)
+                        {
+                            // Always truncate binary blobs. We don't have a ContentType, so detect them using the request name.
+                            if ((requestHandler != null && requestHandler.Name == "GetMesh"))
+                            {
+                                if (output.Length > WebUtil.MaxRequestDiagLength)
+                                    output = output.Substring(0, WebUtil.MaxRequestDiagLength) + "...";
+                            }
+                        }
+
+                        WebUtil.LogResponseDetail(output);
+                    }
+
                     if (!response.SendChunked && response.ContentLength64 <= 0)
                         response.ContentLength64 = buffer.LongLength;
 
@@ -743,7 +761,7 @@ namespace OpenSim.Framework.Servers.HttpServer
                 if (tickdiff > 3000 && requestHandler != null && requestHandler.Name != "GetTexture")
                 {
                     m_log.InfoFormat(
-                        "[BASE HTTP SERVER]: Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms",
+                        "[LOGHTTP] Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms",
                         RequestNumber,
                         requestMethod,
                         uriString,
@@ -755,7 +773,7 @@ namespace OpenSim.Framework.Servers.HttpServer
                 else if (DebugLevel >= 4)
                 {
                     m_log.DebugFormat(
-                        "[BASE HTTP SERVER]: HTTP IN {0} :{1} took {2}ms",
+                        "[LOGHTTP] HTTP IN {0} :{1} took {2}ms",
                         RequestNumber,
                         Port,
                         tickdiff);
@@ -766,7 +784,7 @@ namespace OpenSim.Framework.Servers.HttpServer
         private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler)
         {
             m_log.DebugFormat(
-                "[BASE HTTP SERVER]: HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}",
+                "[LOGHTTP] HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}",
                 RequestNumber,
                 Port,
                 request.HttpMethod,
@@ -782,7 +800,7 @@ namespace OpenSim.Framework.Servers.HttpServer
         private void LogIncomingToContentTypeHandler(OSHttpRequest request)
         {
             m_log.DebugFormat(
-                "[BASE HTTP SERVER]: HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}",
+                "[LOGHTTP] HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}",
                 RequestNumber,
                 Port,
                 string.IsNullOrEmpty(request.ContentType) ? "not set" : request.ContentType,
@@ -797,7 +815,7 @@ namespace OpenSim.Framework.Servers.HttpServer
         private void LogIncomingToXmlRpcHandler(OSHttpRequest request)
         {
             m_log.DebugFormat(
-                "[BASE HTTP SERVER]: HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}",
+                "[LOGHTTP] HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}",
                 RequestNumber,
                 Port,
                 request.HttpMethod,
@@ -810,26 +828,32 @@ namespace OpenSim.Framework.Servers.HttpServer
 
         private void LogIncomingInDetail(OSHttpRequest request)
         {
-            using (StreamReader reader = new StreamReader(Util.Copy(request.InputStream), Encoding.UTF8))
+            if (request.ContentType == "application/octet-stream")
+                return; // never log these; they're just binary data
+
+            Stream inputStream = Util.Copy(request.InputStream);
+
+            if (request.ContentType == "application/x-gzip")
+                inputStream = new GZipStream(inputStream, System.IO.Compression.CompressionMode.Decompress);
+
+            using (StreamReader reader = new StreamReader(inputStream, Encoding.UTF8))
             {
                 string output;
 
                 if (DebugLevel == 5)
                 {
-                    const int sampleLength = 80;
+                    char[] chars = new char[WebUtil.MaxRequestDiagLength + 1];  // +1 so we know to add "..." only if needed
-                    char[] sampleChars = new char[sampleLength + 3];
+                    int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1);
-                    reader.Read(sampleChars, 0, sampleLength);
+                    output = new string(chars, 0, Math.Min(len, WebUtil.MaxRequestDiagLength));
-                    sampleChars[80] = '.';
+                    if (len > WebUtil.MaxRequestDiagLength)
-                    sampleChars[81] = '.';
+                        output += "...";
-                    sampleChars[82] = '.';
-                    output = new string(sampleChars);
                 }
                 else
                 {
                     output = reader.ReadToEnd();
                 }
 
-                m_log.DebugFormat("[BASE HTTP SERVER]: {0}", output.Replace("\n", @"\n"));
+                m_log.DebugFormat("[LOGHTTP] {0}", Util.BinaryToASCII(output));
             }
         }
 

OpenSim/Framework/Util.cs

@@ -1510,6 +1510,46 @@ namespace OpenSim.Framework
             return result;
         }
 
+        public static void BinaryToASCII(char[] chars)
+        {
+            for (int i = 0; i < chars.Length; i++)
+            {
+                char ch = chars[i];
+                if (ch < 32 || ch > 127)
+                    chars[i] = '.';
+            }
+        }
+
+        public static string BinaryToASCII(string src)
+        {
+            char[] chars = src.ToCharArray();
+            BinaryToASCII(chars);
+            return new String(chars);
+        }
+
+        /// <summary>
+        /// Reads a known number of bytes from a stream.
+        /// Throws EndOfStreamException if the stream doesn't contain enough data.
+        /// </summary>
+        /// <param name="stream">The stream to read data from</param>
+        /// <param name="data">The array to write bytes into. The array
+        /// will be completely filled from the stream, so an appropriate
+        /// size must be given.</param>
+        public static void ReadStream(Stream stream, byte[] data)
+        {
+            int offset = 0;
+            int remaining = data.Length;
+
+            while (remaining > 0)
+            {
+                int read = stream.Read(data, offset, remaining);
+                if (read <= 0)
+                    throw new EndOfStreamException(String.Format("End of stream reached with {0} bytes left to read", remaining));
+                remaining -= read;
+                offset += read;
+            }
+        }
+
         public static Guid GetHashGuid(string data, string salt)
         {
             byte[] hash = ComputeMD5Hash(data + salt);

OpenSim/Framework/WebUtil.cs

@@ -89,8 +89,9 @@ namespace OpenSim.Framework
         /// <remarks>
         /// This is to truncate any really large post data, such as an asset.  In theory, the first section should
         /// give us useful information about the call (which agent it relates to if applicable, etc.).
+        /// This is also used to truncate messages when using DebugLevel 5.
         /// </remarks>
-        public const int MaxRequestDiagLength = 100;
+        public const int MaxRequestDiagLength = 200;
 
         /// <summary>
         /// Dictionary of end points
@@ -164,6 +165,11 @@ namespace OpenSim.Framework
         }
 
         public static void LogOutgoingDetail(Stream outputStream)
+        {
+            LogOutgoingDetail("", outputStream);
+        }
+
+        public static void LogOutgoingDetail(string context, Stream outputStream)
         {
             using (StreamReader reader = new StreamReader(Util.Copy(outputStream), Encoding.UTF8))
             {
@@ -171,29 +177,43 @@ namespace OpenSim.Framework
 
                 if (DebugLevel == 5)
                 {
-                    const int sampleLength = 80;
+                    char[] chars = new char[WebUtil.MaxRequestDiagLength + 1];  // +1 so we know to add "..." only if needed
-                    char[] sampleChars = new char[sampleLength];
+                    int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1);
-                    reader.Read(sampleChars, 0, sampleLength);
+                    output = new string(chars, 0, len);
-                    output = new string(sampleChars);
                 }
                 else
                 {
                     output = reader.ReadToEnd();
                 }
 
-                LogOutgoingDetail(output);
+                LogOutgoingDetail(context, output);
             }
         }
 
         public static void LogOutgoingDetail(string output)
+        {
+            LogOutgoingDetail("", output);
+        }
+
+        public static void LogOutgoingDetail(string context, string output)
         {
             if (DebugLevel == 5)
             {
-                output = output.Substring(0, 80);
+                if (output.Length > MaxRequestDiagLength)
-                output = output + "...";
+                    output = output.Substring(0, MaxRequestDiagLength) + "...";
             }
 
-            m_log.DebugFormat("[WEB UTIL]: {0}", output.Replace("\n", @"\n"));
+            m_log.DebugFormat("[LOGHTTP]: {0}{1}", context, Util.BinaryToASCII(output));
+        }
+
+        public static void LogResponseDetail(Stream inputStream)
+        {
+            LogOutgoingDetail("RESPONSE: ", inputStream);
+        }
+
+        public static void LogResponseDetail(string input)
+        {
+            LogOutgoingDetail("RESPONSE: ", input);
         }
 
         private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
@@ -202,7 +222,7 @@ namespace OpenSim.Framework
 
             if (DebugLevel >= 3)
                 m_log.DebugFormat(
-                    "[WEB UTIL]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})",
+                    "[LOGHTTP]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})",
                     reqnum, method, url, timeout, compressed);
 
             string errorMessage = "unknown error";
@@ -268,7 +288,9 @@ namespace OpenSim.Framework
                         using (StreamReader reader = new StreamReader(responseStream))
                         {
                             string responseStr = reader.ReadToEnd();
-                            // m_log.DebugFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr);
+                            // m_log.DebugFormat("[LOGHTTP]: <{0}> response is <{1}>",reqnum,responseStr);
+                            if (WebUtil.DebugLevel >= 5)
+                                WebUtil.LogResponseDetail(responseStr);
                             return CanonicalizeResults(responseStr);
                         }
                     }
@@ -292,7 +314,7 @@ namespace OpenSim.Framework
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
                 if (tickdiff > LongCallTime)
                     m_log.InfoFormat(
-                        "[WEB UTIL]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+                        "[LOGHTTP]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
                         reqnum,
                         method,
                         url,
@@ -303,12 +325,12 @@ namespace OpenSim.Framework
                             : "");
                 else if (DebugLevel >= 4)
                     m_log.DebugFormat(
-                        "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+                        "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
                         reqnum, tickdiff, tickdata);
             }
            
             m_log.DebugFormat(
-                "[WEB UTIL]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage);
+                "[LOGHTTP]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage);
 
             return ErrorResponseMap(errorMessage);
         }
@@ -387,7 +409,7 @@ namespace OpenSim.Framework
 
             if (DebugLevel >= 3)
                 m_log.DebugFormat(
-                    "[WEB UTIL]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})",
+                    "[LOGHTTP]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})",
                     reqnum, method, url, timeout);
             
             string errorMessage = "unknown error";
@@ -431,6 +453,8 @@ namespace OpenSim.Framework
                         using (StreamReader reader = new StreamReader(responseStream))
                         {
                             string responseStr = reader.ReadToEnd();
+                            if (WebUtil.DebugLevel >= 5)
+                                WebUtil.LogResponseDetail(responseStr);
                             OSD responseOSD = OSDParser.Deserialize(responseStr);
 
                             if (responseOSD.Type == OSDType.Map)
@@ -457,7 +481,7 @@ namespace OpenSim.Framework
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
                 if (tickdiff > LongCallTime)
                     m_log.InfoFormat(
-                        "[WEB UTIL]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+                        "[LOGHTTP]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
                         reqnum,
                         method,
                         url,
@@ -468,11 +492,11 @@ namespace OpenSim.Framework
                             : "");
                 else if (DebugLevel >= 4)
                     m_log.DebugFormat(
-                        "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+                        "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
                         reqnum, tickdiff, tickdata);
             }
 
-            m_log.WarnFormat("[WEB UTIL]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage);
+            m_log.WarnFormat("[LOGHTTP]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage);
 
             return ErrorResponseMap(errorMessage);
         }
@@ -753,7 +777,7 @@ namespace OpenSim.Framework
 
             if (WebUtil.DebugLevel >= 3)
                 m_log.DebugFormat(
-                    "[WEB UTIL]: HTTP OUT {0} AsynchronousRequestObject {1} {2}",
+                    "[LOGHTTP]: HTTP OUT {0} AsynchronousRequestObject {1} {2}",
                     reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
@@ -793,14 +817,15 @@ namespace OpenSim.Framework
 
                     int length = (int)buffer.Length;
                     request.ContentLength = length;
+                    byte[] data = buffer.ToArray();
 
                     if (WebUtil.DebugLevel >= 5)
-                        WebUtil.LogOutgoingDetail(buffer);
+                        WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
 
                     request.BeginGetRequestStream(delegate(IAsyncResult res)
                     {
                         using (Stream requestStream = request.EndGetRequestStream(res))
-                            requestStream.Write(buffer.ToArray(), 0, length);
+                            requestStream.Write(data, 0, length);
 
                         // capture how much time was spent writing
                         tickdata = Util.EnvironmentTickCountSubtract(tickstart);
@@ -812,7 +837,11 @@ namespace OpenSim.Framework
                                 try
                                 {
                                     using (Stream respStream = response.GetResponseStream())
+                                    {
+                                        if (WebUtil.DebugLevel >= 5)
+                                            WebUtil.LogResponseDetail(respStream);
                                         deserial = (TResponse)deserializer.Deserialize(respStream);
+                                    }
                                 }
                                 catch (System.InvalidOperationException)
                                 {
@@ -837,7 +866,11 @@ namespace OpenSim.Framework
                                 try
                                 {
                                     using (Stream respStream = response.GetResponseStream())
+                                    {
+                                        if (WebUtil.DebugLevel >= 5)
+                                            WebUtil.LogResponseDetail(respStream);
                                         deserial = (TResponse)deserializer.Deserialize(respStream);
+                                    }
                                 }
                                 catch (System.InvalidOperationException)
                                 {
@@ -907,7 +940,7 @@ namespace OpenSim.Framework
                     }
 
                     m_log.InfoFormat(
-                        "[ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+                        "[LOGHTTP]: [ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
                         reqnum,
                         verb,
                         requestUrl,
@@ -918,7 +951,7 @@ namespace OpenSim.Framework
                 else if (WebUtil.DebugLevel >= 4)
                 {
                     m_log.DebugFormat(
-                        "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+                        "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
                         reqnum, tickdiff, tickdata);
                 }
             }
@@ -951,7 +984,7 @@ namespace OpenSim.Framework
 
             if (WebUtil.DebugLevel >= 3)
                 m_log.DebugFormat(
-                    "[WEB UTIL]: HTTP OUT {0} SynchronousRestForms {1} {2}",
+                    "[LOGHTTP]: HTTP OUT {0} SynchronousRestForms {1} {2}",
                     reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
@@ -978,15 +1011,16 @@ namespace OpenSim.Framework
 
                     length = (int)obj.Length;
                     request.ContentLength = length;
+                    byte[] data = buffer.ToArray();
 
                     if (WebUtil.DebugLevel >= 5)
-                        WebUtil.LogOutgoingDetail(buffer);
+                        WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
 
                     Stream requestStream = null;
                     try
                     {
                         requestStream = request.GetRequestStream();
-                        requestStream.Write(buffer.ToArray(), 0, length);
+                        requestStream.Write(data, 0, length);
                     }
                     catch (Exception e)
                     {
@@ -1036,7 +1070,7 @@ namespace OpenSim.Framework
             int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
             if (tickdiff > WebUtil.LongCallTime)
                 m_log.InfoFormat(
-                    "[FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+                    "[LOGHTTP]: [FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
                     reqnum,
                     verb,
                     requestUrl,
@@ -1045,9 +1079,12 @@ namespace OpenSim.Framework
                     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",
+                    "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
                     reqnum, tickdiff, tickdata);
 
+            if (WebUtil.DebugLevel >= 5)
+                WebUtil.LogResponseDetail(respstring);
+
             return respstring;
         }
 
@@ -1089,7 +1126,7 @@ namespace OpenSim.Framework
 
             if (WebUtil.DebugLevel >= 3)
                 m_log.DebugFormat(
-                    "[WEB UTIL]: HTTP OUT {0} SynchronousRestObject {1} {2}",
+                    "[LOGHTTP]: HTTP OUT {0} SynchronousRestObject {1} {2}",
                     reqnum, verb, requestUrl);
 
             int tickstart = Util.EnvironmentTickCount();
@@ -1126,14 +1163,15 @@ namespace OpenSim.Framework
 
                     int length = (int)buffer.Length;
                     request.ContentLength = length;
+                    byte[] data = buffer.ToArray();
 
                     if (WebUtil.DebugLevel >= 5)
-                        WebUtil.LogOutgoingDetail(buffer);
+                        WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
 
                     try
                     {
                         using (Stream requestStream = request.GetRequestStream())
-                            requestStream.Write(buffer.ToArray(), 0, length);
+                            requestStream.Write(data, 0, length);
                     }
                     catch (Exception e)
                     {
@@ -1159,7 +1197,21 @@ namespace OpenSim.Framework
                             using (Stream respStream = resp.GetResponseStream())
                             {
                                 XmlSerializer deserializer = new XmlSerializer(typeof(TResponse));
-                                deserial = (TResponse)deserializer.Deserialize(respStream);
+
+                                if (WebUtil.DebugLevel >= 5)
+                                {
+                                    byte[] data = new byte[resp.ContentLength];
+                                    Util.ReadStream(respStream, data);
+                                
+                                    WebUtil.LogResponseDetail(System.Text.Encoding.UTF8.GetString(data));
+
+                                    using (MemoryStream temp = new MemoryStream(data))
+                                        deserial = (TResponse)deserializer.Deserialize(temp);
+                                }
+                                else
+                                {
+                                    deserial = (TResponse)deserializer.Deserialize(respStream);
+                                }
                             }
                         }
                         else
@@ -1210,7 +1262,7 @@ namespace OpenSim.Framework
                     }
 
                     m_log.InfoFormat(
-                        "[SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+                        "[LOGHTTP]: [SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
                         reqnum,
                         verb,
                         requestUrl,
@@ -1221,7 +1273,7 @@ namespace OpenSim.Framework
                 else if (WebUtil.DebugLevel >= 4)
                 {
                     m_log.DebugFormat(
-                        "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+                        "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
                         reqnum, tickdiff, tickdata);
                 }
             }