1 files changed, 196 insertions, 81 deletions

diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index 11967c9..6a40cd5 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -53,19 +53,36 @@ namespace OpenSim.Framework
                 LogManager.GetLogger(
                 MethodBase.GetCurrentMethod().DeclaringType);
 
-        private static int m_requestNumber = 0;
+        /// <summary>
+        /// Request number for diagnostic purposes.
+        /// </summary>
+        public static int RequestNumber = 0;
 
-        // this is the header field used to communicate the local request id
-        // used for performance and debugging
+        /// <summary>
+        /// this is the header field used to communicate the local request id
+        /// used for performance and debugging
+        /// </summary>
         public const string OSHeaderRequestID = "opensim-request-id";
 
-        // number of milliseconds a call can take before it is considered
-        // a "long" call for warning & debugging purposes
-        public const int LongCallTime = 500;
+        /// <summary>
+        /// Number of milliseconds a call can take before it is considered
+        /// a "long" call for warning & debugging purposes
+        /// </summary>
+        public const int LongCallTime = 3000;
+
+        /// <summary>
+        /// The maximum length of any data logged because of a long request time.
+        /// </summary>
+        /// <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.).
+        /// </remarks>
+        public const int MaxRequestDiagLength = 100;
 
-        // dictionary of end points
+        /// <summary>
+        /// Dictionary of end points
+        /// </summary>
         private static Dictionary<string,object> m_endpointSerializer = new Dictionary<string,object>();
-        
 
         private static object EndPointLock(string url)
         {
@@ -128,12 +145,13 @@ namespace OpenSim.Framework
 
         private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
         {
-            int reqnum = m_requestNumber++;
+            int reqnum = RequestNumber++;
             // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
 
             string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
             int tickdata = 0;
+            string strBuffer = null;
 
             try
             {
@@ -148,7 +166,7 @@ namespace OpenSim.Framework
                 // If there is some input, write it into the request
                 if (data != null)
                 {
-                    string strBuffer =  OSDParser.SerializeJsonString(data);
+                    strBuffer =  OSDParser.SerializeJsonString(data);
                     byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer);
 
                     if (compressed)
@@ -209,11 +227,18 @@ namespace OpenSim.Framework
             }
             finally
             {
-                // This just dumps a warning for any operation that takes more than 100 ms
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
                 if (tickdiff > LongCallTime)
-                    m_log.DebugFormat("[WEB UTIL]: osd request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
-                                     reqnum,url,method,tickdiff,tickdata);
+                    m_log.InfoFormat(
+                        "[OSD REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+                        reqnum,
+                        method,
+                        url,
+                        tickdiff,
+                        tickdata,
+                        strBuffer != null
+                            ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer)
+                            : "");
             }
            
             m_log.DebugFormat(
@@ -291,17 +316,17 @@ namespace OpenSim.Framework
 
         private static OSDMap ServiceFormRequestWorker(string url, NameValueCollection data, int timeout)
         {
-            int reqnum = m_requestNumber++;
+            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);
             
             string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
             int tickdata = 0;
+            string queryString = null;
 
             try
             {
-                
                 HttpWebRequest request = (HttpWebRequest)HttpWebRequest.Create(url);
                 request.Method = "POST";
                 request.Timeout = timeout;
@@ -312,7 +337,7 @@ namespace OpenSim.Framework
                 
                 if (data != null)
                 {
-                    string queryString = BuildQueryString(data);
+                    queryString = BuildQueryString(data);
                     byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString);
                     
                     request.ContentLength = buffer.Length;
@@ -355,11 +380,19 @@ namespace OpenSim.Framework
             {
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
                 if (tickdiff > LongCallTime)
-                    m_log.InfoFormat("[WEB UTIL]: form request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
-                                     reqnum,url,method,tickdiff,tickdata);
+                    m_log.InfoFormat(
+                        "[SERVICE FORM]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+                        reqnum,
+                        method,
+                        url,
+                        tickdiff,
+                        tickdata,
+                        queryString != null
+                            ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString
+                            : "");
             }
 
-            m_log.WarnFormat("[WEB UTIL]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
+            m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
 
             return ErrorResponseMap(errorMessage);
         }
@@ -640,8 +673,6 @@ namespace OpenSim.Framework
 
             return new string[0];
         }
-
-
     }
 
     public static class AsynchronousRestObjectRequester
@@ -664,6 +695,12 @@ namespace OpenSim.Framework
         public static void MakeRequest<TRequest, TResponse>(string verb,
                 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);
+
+            int tickstart = Util.EnvironmentTickCount();
+            int tickdata = 0;
+
             //            m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} {1}", verb, requestUrl);
 
             Type type = typeof(TRequest);
@@ -674,12 +711,13 @@ namespace OpenSim.Framework
             XmlSerializer deserializer = new XmlSerializer(typeof(TResponse));
 
             request.Method = verb;
+            MemoryStream buffer = null;
 
             if (verb == "POST")
             {
                 request.ContentType = "text/xml";
 
-                MemoryStream buffer = new MemoryStream();
+                buffer = new MemoryStream();
 
                 XmlWriterSettings settings = new XmlWriterSettings();
                 settings.Encoding = Encoding.UTF8;
@@ -701,6 +739,9 @@ namespace OpenSim.Framework
                     requestStream.Write(buffer.ToArray(), 0, length);
                     requestStream.Close();
 
+                    // capture how much time was spent writing
+                    tickdata = Util.EnvironmentTickCountSubtract(tickstart);
+
                     request.BeginGetResponse(delegate(IAsyncResult ar)
                     {
                         response = request.EndGetResponse(ar);
@@ -726,88 +767,108 @@ namespace OpenSim.Framework
 
                     }, null);
                 }, null);
-
-
-                return;
             }
-
-            request.BeginGetResponse(delegate(IAsyncResult res2)
+            else
             {
-                try
+                request.BeginGetResponse(delegate(IAsyncResult res2)
                 {
-                    // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
-                    // documented in MSDN
-                    response = request.EndGetResponse(res2);
-
-                    Stream respStream = null;
                     try
                     {
-                        respStream = response.GetResponseStream();
-                        deserial = (TResponse)deserializer.Deserialize(respStream);
-                    }
-                    catch (System.InvalidOperationException)
-                    {
-                    }
-                    finally
-                    {
-                        respStream.Close();
-                        response.Close();
+                        // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
+                        // documented in MSDN
+                        response = request.EndGetResponse(res2);
+    
+                        Stream respStream = null;
+                        try
+                        {
+                            respStream = response.GetResponseStream();
+                            deserial = (TResponse)deserializer.Deserialize(respStream);
+                        }
+                        catch (System.InvalidOperationException)
+                        {
+                        }
+                        finally
+                        {
+                            respStream.Close();
+                            response.Close();
+                        }
                     }
-                }
-                catch (WebException e)
-                {
-                    if (e.Status == WebExceptionStatus.ProtocolError)
+                    catch (WebException e)
                     {
-                        if (e.Response is HttpWebResponse)
+                        if (e.Status == WebExceptionStatus.ProtocolError)
                         {
-                            HttpWebResponse httpResponse = (HttpWebResponse)e.Response;
-
-                            if (httpResponse.StatusCode != HttpStatusCode.NotFound)
+                            if (e.Response is HttpWebResponse)
                             {
-                                // We don't appear to be handling any other status codes, so log these feailures to that
-                                // people don't spend unnecessary hours hunting phantom bugs.
-                                m_log.DebugFormat(
-                                    "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}",
-                                    verb, requestUrl, httpResponse.StatusCode);
+                                HttpWebResponse httpResponse = (HttpWebResponse)e.Response;
+    
+                                if (httpResponse.StatusCode != HttpStatusCode.NotFound)
+                                {
+                                    // We don't appear to be handling any other status codes, so log these feailures to that
+                                    // people don't spend unnecessary hours hunting phantom bugs.
+                                    m_log.DebugFormat(
+                                        "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}",
+                                        verb, requestUrl, httpResponse.StatusCode);
+                                }
                             }
                         }
+                        else
+                        {
+                            m_log.ErrorFormat(
+                                "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}",
+                                verb, requestUrl, e.Status, e.Message);
+                        }
                     }
-                    else
+                    catch (Exception e)
                     {
                         m_log.ErrorFormat(
-                            "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}",
-                            verb, requestUrl, e.Status, e.Message);
+                            "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}",
+                            verb, requestUrl, e.Message, e.StackTrace);
                     }
-                }
-                catch (Exception e)
-                {
-                    m_log.ErrorFormat(
-                        "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}",
-                        verb, requestUrl, e.Message, e.StackTrace);
-                }
+    
+                    //  m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString());
+
+                    try
+                    {
+                        action(deserial);
+                    }
+                    catch (Exception e)
+                    {
+                        m_log.ErrorFormat(
+                            "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}",
+                            verb, requestUrl, e.Message, e.StackTrace);
+                    }
+    
+                }, null);
+            }
 
-                //  m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString());
+            int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+            if (tickdiff > WebUtil.LongCallTime)
+            {
+                string originalRequest = null;
 
-                try
-                {
-                    action(deserial);
-                }
-                catch (Exception e)
+                if (buffer != null)
                 {
-                    m_log.ErrorFormat(
-                        "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}",
-                        verb, requestUrl, e.Message, e.StackTrace);
+                    originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
+
+                    if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
+                        originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
                 }
 
-            }, null);
+                m_log.InfoFormat(
+                    "[ASYNC REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+                    reqnum,
+                    verb,
+                    requestUrl,
+                    tickdiff,
+                    tickdata,
+                    originalRequest);
+            }
         }
     }
 
     public static class SynchronousRestFormsRequester
     {
-        private static readonly ILog m_log =
-                LogManager.GetLogger(
-                MethodBase.GetCurrentMethod().DeclaringType);
+        private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
 
         /// <summary>
         /// Perform a synchronous REST request.
@@ -821,6 +882,12 @@ namespace OpenSim.Framework
         /// the request.  You'll want to make sure you deal with this as they're not uncommon</exception>
         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);
+
+            int tickstart = Util.EnvironmentTickCount();
+            int tickdata = 0;
+
             WebRequest request = WebRequest.Create(requestUrl);
             request.Method = verb;
             string respstring = String.Empty;
@@ -856,6 +923,9 @@ namespace OpenSim.Framework
                     {
                         if (requestStream != null)
                             requestStream.Close();
+
+                        // capture how much time was spent writing
+                        tickdata = Util.EnvironmentTickCountSubtract(tickstart);
                     }
                 }
 
@@ -894,6 +964,18 @@ namespace OpenSim.Framework
                     m_log.DebugFormat("[FORMS]: InvalidOperationException on receiving {0} {1}", verb, requestUrl);
                 }
             }
+
+            int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+            if (tickdiff > WebUtil.LongCallTime)
+                m_log.InfoFormat(
+                    "[FORMS]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+                    reqnum,
+                    verb,
+                    requestUrl,
+                    tickdiff,
+                    tickdata,
+                    obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj);
+
             return respstring;
         }
     }
@@ -921,6 +1003,12 @@ namespace OpenSim.Framework
 
         public static TResponse MakeRequest<TRequest, TResponse>(string verb, string requestUrl, TRequest obj, int pTimeout)
         {
+            int reqnum = WebUtil.RequestNumber++;
+            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+            int tickstart = Util.EnvironmentTickCount();
+            int tickdata = 0;
+
             Type type = typeof(TRequest);
             TResponse deserial = default(TResponse);
 
@@ -928,12 +1016,13 @@ namespace OpenSim.Framework
             request.Method = verb;
             if (pTimeout != 0)
                 request.Timeout = pTimeout * 1000;
+            MemoryStream buffer = null;
 
             if ((verb == "POST") || (verb == "PUT"))
             {
                 request.ContentType = "text/xml";
 
-                MemoryStream buffer = new MemoryStream();
+                buffer = new MemoryStream();
 
                 XmlWriterSettings settings = new XmlWriterSettings();
                 settings.Encoding = Encoding.UTF8;
@@ -966,6 +1055,9 @@ namespace OpenSim.Framework
                 {
                     if (requestStream != null)
                         requestStream.Close();
+
+                    // capture how much time was spent writing
+                    tickdata = Util.EnvironmentTickCountSubtract(tickstart);
                 }
             }
 
@@ -1013,7 +1105,30 @@ namespace OpenSim.Framework
                     verb, requestUrl, e.Message, e.StackTrace);
             }
 
+            int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+            if (tickdiff > WebUtil.LongCallTime)
+            {
+                string originalRequest = null;
+
+                if (buffer != null)
+                {
+                    originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
+
+                    if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
+                        originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
+                }
+
+                m_log.InfoFormat(
+                    "[SynchronousRestObjectRequester]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+                    reqnum,
+                    verb,
+                    requestUrl,
+                    tickdiff,
+                    tickdata,
+                    originalRequest);
+            }
+
             return deserial;
         }
     }
-}
\ No newline at end of file
+}