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.
0.7.4.1
Justin Clark-Casey (justincc) 2012-06-13 00:03:44 +01:00
parent 2ca31a9841
commit c6e375291a
7 changed files with 174 additions and 322 deletions

View File

@ -539,7 +539,6 @@ namespace OpenSim.ApplicationPlugins.Rest.Inventory
/// path has not already been registered, the method is added to the active
/// handler table.
/// </summary>
public void AddStreamHandler(string httpMethod, string path, RestMethod method)
{
if (!IsEnabled)

View File

@ -77,7 +77,6 @@ namespace OpenSim.Capabilities.Handlers
{
m_log.Error("[GETTEXTURE]: Cannot fetch texture " + textureStr + " without an asset service");
httpResponse.StatusCode = (int)System.Net.HttpStatusCode.NotFound;
return null;
}
UUID textureID;
@ -115,7 +114,6 @@ namespace OpenSim.Capabilities.Handlers
// "[GETTEXTURE]: For texture {0} sending back response {1}, data length {2}",
// textureID, httpResponse.StatusCode, httpResponse.ContentLength);
httpResponse.Send();
return null;
}

View File

@ -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();
}
}
}
else
{
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);
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;
}
}
request.InputStream.Close();
// HTTP IN support. The script engine takes it from here
// Nothing to worry about for us.
//
if (buffer == null)
return;
request.InputStream.Close();
if (buffer != null)
{
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;
response.OutputStream.Write(buffer, 0, buffer.Length);
}
if (request.AcceptTypes != null && request.AcceptTypes.Length > 0)
{
foreach (string strAccept in request.AcceptTypes)
{
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);
// 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;
HandleLLSDRequests(request, response);
return;
}
}
}
response.Send();
switch (request.ContentType)
{
case null:
case "text/html":
//response.OutputStream.Close();
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))
{
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))
{
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;
}
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.
HandleXmlRpcRequests(request, response);
return;
}
//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()

View File

@ -128,11 +128,5 @@ namespace OpenSim.Framework.Servers.HttpServer
/// <param name="value">string containing the header field
/// value</param>
void AddHeader(string key, string value);
/// <summary>
/// Send the response back to the remote client
/// </summary>
void Send();
}
}
}

View File

@ -321,13 +321,12 @@ namespace OpenSim.Framework.Servers.HttpServer
{
_httpResponse.Body.Flush();
_httpResponse.Send();
}
public void FreeContext()
{
if (_httpClientContext != null)
_httpClientContext.Close();
}
}
}

View File

@ -140,9 +140,8 @@ namespace OpenSim.Framework.Servers.HttpServer
foreach (object o in m_requests)
{
PollServiceHttpRequest req = (PollServiceHttpRequest) o;
m_server.DoHTTPGruntWork(
req.PollServiceArgs.NoEvents(req.RequestID, req.PollServiceArgs.Id),
new OSHttpResponse(new HttpResponse(req.HttpContext, req.Request), req.HttpContext));
PollServiceWorkerThread.DoHTTPGruntWork(
m_server, req, req.PollServiceArgs.NoEvents(req.RequestID, req.PollServiceArgs.Id));
}
m_requests.Clear();
@ -151,6 +150,7 @@ namespace OpenSim.Framework.Servers.HttpServer
{
t.Abort();
}
m_running = false;
}
}

View File

@ -90,15 +90,16 @@ namespace OpenSim.Framework.Servers.HttpServer
}
Hashtable responsedata = req.PollServiceArgs.GetEvents(req.RequestID, req.PollServiceArgs.Id, str.ReadToEnd());
m_server.DoHTTPGruntWork(responsedata,
new OSHttpResponse(new HttpResponse(req.HttpContext, req.Request),req.HttpContext));
DoHTTPGruntWork(m_server, req, responsedata);
}
else
{
if ((Environment.TickCount - req.RequestTime) > m_timeout)
{
m_server.DoHTTPGruntWork(req.PollServiceArgs.NoEvents(req.RequestID, req.PollServiceArgs.Id),
new OSHttpResponse(new HttpResponse(req.HttpContext, req.Request),req.HttpContext));
DoHTTPGruntWork(
m_server,
req,
req.PollServiceArgs.NoEvents(req.RequestID, req.PollServiceArgs.Id));
}
else
{
@ -119,5 +120,47 @@ namespace OpenSim.Framework.Servers.HttpServer
{
m_request.Enqueue(pPollServiceHttpRequest);
}
/// <summary>
/// FIXME: This should be part of BaseHttpServer
/// </summary>
internal static void DoHTTPGruntWork(BaseHttpServer server, PollServiceHttpRequest req, Hashtable responsedata)
{
OSHttpResponse response
= new OSHttpResponse(new HttpResponse(req.HttpContext, req.Request), req.HttpContext);
byte[] buffer
= server.DoHTTPGruntWork(
responsedata, new OSHttpResponse(new HttpResponse(req.HttpContext, req.Request), req.HttpContext));
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(string.Format("[POLL SERVICE WORKER THREAD]: Error ", ex));
}
finally
{
//response.OutputStream.Close();
try
{
response.OutputStream.Flush();
response.Send();
//if (!response.KeepAlive && response.ReuseContext)
// response.FreeContext();
}
catch (Exception e)
{
m_log.Warn(String.Format("[POLL SERVICE WORKER THREAD]: Error ", e));
}
}
}
}
}
}