Don't include time to transmit response back to requester when assessing slow handling of requests.

This is to avoid logging a 'slow' request when the source of delay is the viewer in processing a response.
This is not something we can do much about on the server end - it's server-side delay that we're interested in.
To ensure consistency, this commit also had to refactor and simplify inbound non-poll network request handling, though there should be no functional change.
IOSHttpResponse no longer exposes the Send() method, only classes in OpenSim.Framework.Servers.HttpServer should be doing this.
Only the GetTextureHandler was sending its own response.  Now it leaves this to BaseHttpServer, like all other core handlers.

1 files changed, 116 insertions, 297 deletions

diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
index 401dfd3..ef6e259 100644
--- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
+++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
@@ -408,7 +408,10 @@ namespace OpenSim.Framework.Servers.HttpServer
             string uriString = request.RawUrl;
 
 //            string reqnum = "unknown";
-            int tickstart = Environment.TickCount;
+            int requestStartTick = Environment.TickCount;
+
+            // Will be adjusted later on.
+            int requestEndTick = requestStartTick;
 
             IRequestHandler requestHandler = null;
 
@@ -433,6 +436,7 @@ namespace OpenSim.Framework.Servers.HttpServer
                 {
                     if (HandleAgentRequest(agentHandler, request, response))
                     {
+                        requestEndTick = Environment.TickCount;
                         return;
                     }
                 }
@@ -442,6 +446,7 @@ namespace OpenSim.Framework.Servers.HttpServer
 
                 string path = request.RawUrl;
                 string handlerKey = GetHandlerKey(request.HttpMethod, path);
+                byte[] buffer = null;
 
                 if (TryGetStreamHandler(handlerKey, out requestHandler))
                 {
@@ -450,9 +455,6 @@ namespace OpenSim.Framework.Servers.HttpServer
                             "[BASE HTTP SERVER]: Found stream handler for {0} {1} {2} {3}",
                             request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description);
 
-                    // Okay, so this is bad, but should be considered temporary until everything is IStreamHandler.
-                    byte[] buffer = null;
-
                     response.ContentType = requestHandler.ContentType; // Lets do this defaulting before in case handler has varying content type.
 
                     if (requestHandler is IStreamedRequestHandler)
@@ -507,8 +509,8 @@ namespace OpenSim.Framework.Servers.HttpServer
                             //m_log.Warn("[HTTP]: " + requestBody);
 
                         }
-                        DoHTTPGruntWork(HTTPRequestHandler.Handle(path, keysvals), response);
-                        return;
+
+                        buffer = DoHTTPGruntWork(HTTPRequestHandler.Handle(path, keysvals), response);
                     }
                     else
                     {
@@ -521,133 +523,100 @@ namespace OpenSim.Framework.Servers.HttpServer
                             buffer = memoryStream.ToArray();
                         }
                     }
-
-                    request.InputStream.Close();
-
-                    // HTTP IN support. The script engine takes it from here
-                    // Nothing to worry about for us.
-                    //
-                    if (buffer == null)
-                        return;
-
-                    if (!response.SendChunked)
-                        response.ContentLength64 = buffer.LongLength;
-
-                    try
-                    {
-                        response.OutputStream.Write(buffer, 0, buffer.Length);
-                        //response.OutputStream.Close();
-                    }
-                    catch (HttpListenerException)
-                    {
-                        m_log.WarnFormat("[BASE HTTP SERVER]: HTTP request abnormally terminated.");
-                    }
-                    //response.OutputStream.Close();
-                    try
-                    {
-                        response.Send();
-                        //response.FreeContext();
-                    }
-                    catch (SocketException e)
-                    {
-                        // This has to be here to prevent a Linux/Mono crash
-                        m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                    }
-                    catch (IOException e)
-                    {
-                        m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}. ", e.Message), e);
-                    }
-
-                    return;
                 }
-
-                if (request.AcceptTypes != null && request.AcceptTypes.Length > 0)
+                else
                 {
-                    foreach (string strAccept in request.AcceptTypes)
+                    switch (request.ContentType)
                     {
-                        if (strAccept.Contains("application/llsd+xml") ||
-                            strAccept.Contains("application/llsd+json"))
-                        {
-                            if (DebugLevel >= 1)
-                                m_log.DebugFormat(
-                                    "[BASE HTTP SERVER]: Found application/llsd+xml accept header handler for {0} {1}",
-                                    request.HttpMethod, request.Url.PathAndQuery);
-
-                            HandleLLSDRequests(request, response);
-                            return;
-                        }
-                    }
-                }
-
-                switch (request.ContentType)
-                {
-                    case null:
-                    case "text/html":
-
-                        if (DebugLevel >= 1)
-                            m_log.DebugFormat(
-                                "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
-                                request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
-
-                        HandleHTTPRequest(request, response);
-                        return;
-
-                    case "application/llsd+xml":
-                    case "application/xml+llsd":
-                    case "application/llsd+json":
-
-                        if (DebugLevel >= 1)
-                            m_log.DebugFormat(
-                                "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
-                                request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
-
-                        HandleLLSDRequests(request, response);
-                        return;
-
-                    case "text/xml":
-                    case "application/xml":
-                    case "application/json":
-                    default:
-                        //m_log.Info("[Debug BASE HTTP SERVER]: in default handler");
-                        // Point of note..  the DoWeHaveA methods check for an EXACT path
-                        //                        if (request.RawUrl.Contains("/CAPS/EQG"))
-                        //                        {
-                        //                            int i = 1;
-                        //                        }
-                        //m_log.Info("[Debug BASE HTTP SERVER]: Checking for LLSD Handler");
-                        if (DoWeHaveALLSDHandler(request.RawUrl))
-                        {
+                        case null:
+                        case "text/html":
+    
                             if (DebugLevel >= 1)
                                 m_log.DebugFormat(
                                     "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
                                     request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
-
-                            HandleLLSDRequests(request, response);
-                            return;
-                        }
-
-//                        m_log.DebugFormat("[BASE HTTP SERVER]: Checking for HTTP Handler for request {0}", request.RawUrl);
-                        if (DoWeHaveAHTTPHandler(request.RawUrl))
-                        {
+    
+                            buffer = HandleHTTPRequest(request, response);
+                            break;
+    
+                        case "application/llsd+xml":
+                        case "application/xml+llsd":
+                        case "application/llsd+json":
+    
                             if (DebugLevel >= 1)
                                 m_log.DebugFormat(
                                     "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
                                     request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
+    
+                            buffer = HandleLLSDRequests(request, response);
+                            break;
+    
+                        case "text/xml":
+                        case "application/xml":
+                        case "application/json":
+                        default:
+                            //m_log.Info("[Debug BASE HTTP SERVER]: in default handler");
+                            // Point of note..  the DoWeHaveA methods check for an EXACT path
+                            //                        if (request.RawUrl.Contains("/CAPS/EQG"))
+                            //                        {
+                            //                            int i = 1;
+                            //                        }
+                            //m_log.Info("[Debug BASE HTTP SERVER]: Checking for LLSD Handler");
+                            if (DoWeHaveALLSDHandler(request.RawUrl))
+                            {
+                                if (DebugLevel >= 1)
+                                    m_log.DebugFormat(
+                                        "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
+                                        request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
+    
+                                buffer = HandleLLSDRequests(request, response);
+                            }
+    //                        m_log.DebugFormat("[BASE HTTP SERVER]: Checking for HTTP Handler for request {0}", request.RawUrl);
+                            else if (DoWeHaveAHTTPHandler(request.RawUrl))
+                            {
+                                if (DebugLevel >= 1)
+                                    m_log.DebugFormat(
+                                        "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}",
+                                        request.ContentType, request.HttpMethod, request.Url.PathAndQuery);
+    
+                                buffer = HandleHTTPRequest(request, response);
+                            }
+                            else
+                            {
+    
+                                if (DebugLevel >= 1)
+                                    m_log.DebugFormat(
+                                        "[BASE HTTP SERVER]: Assuming a generic XMLRPC request for {0} {1}",
+                                        request.HttpMethod, request.Url.PathAndQuery);
+    
+                                // generic login request.
+                                buffer = HandleXmlRpcRequests(request, response);
+                            }
+    
+                            break;
+                    }
+                }
 
-                            HandleHTTPRequest(request, response);
-                            return;
-                        }
-
-                        if (DebugLevel >= 1)
-                            m_log.DebugFormat(
-                                "[BASE HTTP SERVER]: Assuming a generic XMLRPC request for {0} {1}",
-                                request.HttpMethod, request.Url.PathAndQuery);
+                request.InputStream.Close();
 
-                        // generic login request.
-                        HandleXmlRpcRequests(request, response);
+                if (buffer != null)
+                {
+                    if (!response.SendChunked)
+                        response.ContentLength64 = buffer.LongLength;
 
-                        return;
+                    response.OutputStream.Write(buffer, 0, buffer.Length);
                 }
+
+                // Do not include the time taken to actually send the response to the caller in the measurement
+                // time.  This is to avoid logging when it's the client that is slow to process rather than the
+                // server
+                requestEndTick = Environment.TickCount;
+
+                response.Send();
+
+                //response.OutputStream.Close();
+
+                //response.FreeContext();
             }
             catch (SocketException e)
             {
@@ -672,8 +641,8 @@ namespace OpenSim.Framework.Servers.HttpServer
             finally
             {
                 // Every month or so this will wrap and give bad numbers, not really a problem
-                // since its just for reporting, tickdiff limit can be adjusted
-                int tickdiff = Environment.TickCount - tickstart;
+                // since its just for reporting
+                int tickdiff = requestEndTick - requestStartTick;
                 if (tickdiff > 3000)
                 {
                     m_log.InfoFormat(
@@ -805,7 +774,7 @@ namespace OpenSim.Framework.Servers.HttpServer
         /// </summary>
         /// <param name="request"></param>
         /// <param name="response"></param>
-        private void HandleXmlRpcRequests(OSHttpRequest request, OSHttpResponse response)
+        private byte[] HandleXmlRpcRequests(OSHttpRequest request, OSHttpResponse response)
         {
             Stream requestStream = request.InputStream;
 
@@ -817,7 +786,7 @@ namespace OpenSim.Framework.Servers.HttpServer
             requestStream.Close();
             //m_log.Debug(requestBody);
             requestBody = requestBody.Replace("<base64></base64>", "");
-            string responseString = String.Empty;
+            string responseString = null;
             XmlRpcRequest xmlRprcRequest = null;
 
             try
@@ -895,6 +864,7 @@ namespace OpenSim.Framework.Servers.HttpServer
                             String.Format("Requested method [{0}] not found", methodName));
                     }
 
+                    response.ContentType = "text/xml";
                     responseString = XmlRpcResponseSerializer.Singleton.Serialize(xmlRpcResponse);
                 }
                 else
@@ -904,82 +874,25 @@ namespace OpenSim.Framework.Servers.HttpServer
                     response.StatusCode = 404;
                     response.StatusDescription = "Not Found";
                     response.ProtocolVersion = "HTTP/1.0";
-                    byte[] buf = Encoding.UTF8.GetBytes("Not found");
+                    responseString = "Not found";
                     response.KeepAlive = false;
 
                     m_log.ErrorFormat(
                         "[BASE HTTP SERVER]: Handler not found for http request {0} {1}",
                         request.HttpMethod, request.Url.PathAndQuery);
-
-                    response.SendChunked = false;
-                    response.ContentLength64 = buf.Length;
-                    response.ContentEncoding = Encoding.UTF8;
-
-                    try
-                    {
-                        response.OutputStream.Write(buf, 0, buf.Length);
-                    }
-                    catch (Exception ex)
-                    {
-                        m_log.Warn("[BASE HTTP SERVER]: Error - " + ex.Message);
-                    }
-                    finally
-                    {
-                        try
-                        {
-                            response.Send();
-                            //response.FreeContext();
-                        }
-                        catch (SocketException e)
-                        {
-                            // This has to be here to prevent a Linux/Mono crash
-                            m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                        }
-                        catch (IOException e)
-                        {
-                            m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0} ", e.Message), e);
-                        }
-                    }
-                    return;
-                    //responseString = "Error";
                 }
             }
 
-            response.ContentType = "text/xml";
-
             byte[] buffer = Encoding.UTF8.GetBytes(responseString);
 
             response.SendChunked = false;
             response.ContentLength64 = buffer.Length;
             response.ContentEncoding = Encoding.UTF8;
-            try
-            {
-                response.OutputStream.Write(buffer, 0, buffer.Length);
-            }
-            catch (Exception ex)
-            {
-                m_log.Warn("[BASE HTTP SERVER]: Error - " + ex.Message);
-            }
-            finally
-            {
-                try
-                {
-                    response.Send();
-                    //response.FreeContext();
-                }
-                catch (SocketException e)
-                {
-                    // This has to be here to prevent a Linux/Mono crash
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                }
-                catch (IOException e)
-                {
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0} ", e.Message), e);
-                }
-            }
+
+            return buffer;
         }
 
-        private void HandleLLSDRequests(OSHttpRequest request, OSHttpResponse response)
+        private byte[] HandleLLSDRequests(OSHttpRequest request, OSHttpResponse response)
         {
             //m_log.Warn("[BASE HTTP SERVER]: We've figured out it's a LLSD Request");
             Stream requestStream = request.InputStream;
@@ -1065,34 +978,7 @@ namespace OpenSim.Framework.Servers.HttpServer
             response.ContentEncoding = Encoding.UTF8;
             response.KeepAlive = true;
 
-            try
-            {
-                response.OutputStream.Write(buffer, 0, buffer.Length);
-            }
-            catch (Exception ex)
-            {
-                m_log.Warn("[BASE HTTP SERVER]: Error - " + ex.Message);
-            }
-            finally
-            {
-                //response.OutputStream.Close();
-                try
-                {
-                    response.Send();
-                    response.OutputStream.Flush();
-                    //response.FreeContext();
-                    //response.OutputStream.Close();
-                }
-                catch (IOException e)
-                {
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: LLSD IOException {0} ", e.Message), e);
-                }
-                catch (SocketException e)
-                {
-                    // This has to be here to prevent a Linux/Mono crash
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: LLSD issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                }
-            }
+            return buffer;
         }
 
         private byte[] BuildLLSDResponse(OSHttpRequest request, OSHttpResponse response, OSD llsdResponse)
@@ -1357,7 +1243,7 @@ namespace OpenSim.Framework.Servers.HttpServer
 
         }
 
-        public void HandleHTTPRequest(OSHttpRequest request, OSHttpResponse response)
+        public byte[] HandleHTTPRequest(OSHttpRequest request, OSHttpResponse response)
         {
 //            m_log.DebugFormat(
 //                "[BASE HTTP SERVER]: HandleHTTPRequest for request to {0}, method {1}",
@@ -1367,15 +1253,14 @@ namespace OpenSim.Framework.Servers.HttpServer
             {
                 case "OPTIONS":
                     response.StatusCode = (int)OSHttpStatusCode.SuccessOk;
-                    return;
+                    return null;
 
                 default:
-                    HandleContentVerbs(request, response);
-                    return;
+                    return HandleContentVerbs(request, response);
             }
         }
 
-        private void HandleContentVerbs(OSHttpRequest request, OSHttpResponse response)
+        private byte[] HandleContentVerbs(OSHttpRequest request, OSHttpResponse response)
         {
 //            m_log.DebugFormat("[BASE HTTP SERVER]: HandleContentVerbs for request to {0}", request.RawUrl);
 
@@ -1391,6 +1276,8 @@ namespace OpenSim.Framework.Servers.HttpServer
             // to display the form, or process it.
             // a better way would be nifty.
 
+            byte[] buffer;
+
             Stream requestStream = request.InputStream;
 
             Encoding encoding = Encoding.UTF8;
@@ -1451,14 +1338,14 @@ namespace OpenSim.Framework.Servers.HttpServer
                 if (foundHandler)
                 {
                     Hashtable responsedata1 = requestprocessor(keysvals);
-                    DoHTTPGruntWork(responsedata1,response);
+                    buffer = DoHTTPGruntWork(responsedata1,response);
 
                     //SendHTML500(response);
                 }
                 else
                 {
 //                    m_log.Warn("[BASE HTTP SERVER]: Handler Not Found");
-                    SendHTML404(response, host);
+                    buffer = SendHTML404(response, host);
                 }
             }
             else
@@ -1468,16 +1355,18 @@ namespace OpenSim.Framework.Servers.HttpServer
                 if (foundHandler)
                 {
                     Hashtable responsedata2 = requestprocessor(keysvals);
-                    DoHTTPGruntWork(responsedata2, response);
+                    buffer = DoHTTPGruntWork(responsedata2, response);
 
                     //SendHTML500(response);
                 }
                 else
                 {
 //                    m_log.Warn("[BASE HTTP SERVER]: Handler Not Found2");
-                    SendHTML404(response, host);
+                    buffer = SendHTML404(response, host);
                 }
             }
+
+            return buffer;
         }
 
         private bool TryGetHTTPHandlerPathBased(string path, out GenericHTTPMethod httpHandler)
@@ -1545,14 +1434,13 @@ namespace OpenSim.Framework.Servers.HttpServer
             }
         }
 
-        internal void DoHTTPGruntWork(Hashtable responsedata, OSHttpResponse response)
+        internal byte[] DoHTTPGruntWork(Hashtable responsedata, OSHttpResponse response)
         {
             //m_log.Info("[BASE HTTP SERVER]: Doing HTTP Grunt work with response");
             int responsecode = (int)responsedata["int_response_code"];
             string responseString = (string)responsedata["str_response_string"];
             string contentType = (string)responsedata["content_type"];
 
-
             if (responsedata.ContainsKey("error_status_text"))
             {
                 response.StatusDescription = (string)responsedata["error_status_text"];
@@ -1616,38 +1504,10 @@ namespace OpenSim.Framework.Servers.HttpServer
             response.ContentLength64 = buffer.Length;
             response.ContentEncoding = Encoding.UTF8;
 
-            try
-            {
-                response.OutputStream.Write(buffer, 0, buffer.Length);
-            }
-            catch (Exception ex)
-            {
-                m_log.Warn("[HTTPD]: Error - " + ex.Message);
-            }
-            finally
-            {
-                //response.OutputStream.Close();
-                try
-                {
-                    response.OutputStream.Flush();
-                    response.Send();
-
-                    //if (!response.KeepAlive && response.ReuseContext)
-                    //    response.FreeContext();
-                }
-                catch (SocketException e)
-                {
-                    // This has to be here to prevent a Linux/Mono crash
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                }
-                catch (IOException e)
-                {
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0} ", e.Message), e);
-                }
-            }
+            return buffer;
         }
 
-        public void SendHTML404(OSHttpResponse response, string host)
+        public byte[] SendHTML404(OSHttpResponse response, string host)
         {
             // I know this statuscode is dumb, but the client doesn't respond to 404s and 500s
             response.StatusCode = 404;
@@ -1660,31 +1520,10 @@ namespace OpenSim.Framework.Servers.HttpServer
             response.ContentLength64 = buffer.Length;
             response.ContentEncoding = Encoding.UTF8;
 
-            try
-            {
-                response.OutputStream.Write(buffer, 0, buffer.Length);
-            }
-            catch (Exception ex)
-            {
-                m_log.Warn("[BASE HTTP SERVER]: Error - " + ex.Message);
-            }
-            finally
-            {
-                //response.OutputStream.Close();
-                try
-                {
-                    response.Send();
-                    //response.FreeContext();
-                }
-                catch (SocketException e)
-                {
-                    // This has to be here to prevent a Linux/Mono crash
-                    m_log.Warn(String.Format("[BASE HTTP SERVER]: XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                }
-            }
+            return buffer;
         }
 
-        public void SendHTML500(OSHttpResponse response)
+        public byte[] SendHTML500(OSHttpResponse response)
         {
             // I know this statuscode is dumb, but the client doesn't respond to 404s and 500s
             response.StatusCode = (int)OSHttpStatusCode.SuccessOk;
@@ -1696,28 +1535,8 @@ namespace OpenSim.Framework.Servers.HttpServer
             response.SendChunked = false;
             response.ContentLength64 = buffer.Length;
             response.ContentEncoding = Encoding.UTF8;
-            try
-            {
-                response.OutputStream.Write(buffer, 0, buffer.Length);
-            }
-            catch (Exception ex)
-            {
-                m_log.Warn("[BASE HTTP SERVER]: Error - " + ex.Message);
-            }
-            finally
-            {
-                //response.OutputStream.Close();
-                try
-                {
-                    response.Send();
-                    //response.FreeContext();
-                }
-                catch (SocketException e)
-                {
-                    // This has to be here to prevent a Linux/Mono crash
-                    m_log.Warn(String.Format("[BASE HTTP SERVER] XmlRpcRequest issue {0}.\nNOTE: this may be spurious on Linux. ", e.Message), e);
-                }
-            }
+
+            return buffer;
         }
 
         public void Start()