OpenSim
/
OpenSimMirror
1
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity

Insert a new log level 4 for HTTP IN and HTTP OUT that will log how long the request took. 

This is only printed if debug http level >= 4 and the request didn't take more than the time considered 'long', in which case the existing log message is printed.
This displaces the previous log levels 4 and 5 which are now 5 and 6 respectively.
connector_plugin
Justin Clark-Casey (justincc) 2012-09-20 23:18:19 +01:00
parent 387a1bb283
commit a5b3989e5d
3 changed files with 87 additions and 32 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

47
OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
View File

@ -54,6 +54,12 @@ namespace OpenSim.Framework.Servers.HttpServer
private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
private HttpServerLogWriter httpserverlog = new HttpServerLogWriter(); private HttpServerLogWriter httpserverlog = new HttpServerLogWriter();
/// <summary>
/// Gets or sets the debug level.
/// </summary>
/// <value>
/// See MainServer.DebugLevel.
/// </value>
public int DebugLevel { get; set; } public int DebugLevel { get; set; }
private volatile int NotSocketErrors = 0; private volatile int NotSocketErrors = 0;
@ -529,8 +535,8 @@ namespace OpenSim.Framework.Servers.HttpServer
if (DebugLevel >= 3) if (DebugLevel >= 3)
m_log.DebugFormat( m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}",
request.ContentType, request.HttpMethod, request.Url.PathAndQuery); request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint);
buffer = HandleHTTPRequest(request, response); buffer = HandleHTTPRequest(request, response);
break; break;
@ -541,8 +547,8 @@ namespace OpenSim.Framework.Servers.HttpServer
if (DebugLevel >= 3) if (DebugLevel >= 3)
m_log.DebugFormat( m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}",
request.ContentType, request.HttpMethod, request.Url.PathAndQuery); request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint);
buffer = HandleLLSDRequests(request, response); buffer = HandleLLSDRequests(request, response);
break; break;
@ -640,7 +646,18 @@ namespace OpenSim.Framework.Servers.HttpServer
uriString, uriString,
requestHandler != null ? requestHandler.Name : "", requestHandler != null ? requestHandler.Name : "",
requestHandler != null ? requestHandler.Description : "", requestHandler != null ? requestHandler.Description : "",
request.RemoteIPEndPoint.ToString(), request.RemoteIPEndPoint,
tickdiff);
}
else if (DebugLevel >= 4)
{
m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN {0} {1} {2} {3} from {4} took {5}ms",
requestMethod,
uriString,
requestHandler != null ? requestHandler.Name : "",
requestHandler != null ? requestHandler.Description : "",
request.RemoteIPEndPoint,
tickdiff); tickdiff);
} }
} }
@ -649,30 +666,30 @@ namespace OpenSim.Framework.Servers.HttpServer
private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler)
{ {
m_log.DebugFormat( m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3}", "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3} from {4}",
request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description); request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description, request.RemoteIPEndPoint);
if (DebugLevel >= 4) if (DebugLevel >= 5)
LogIncomingInDetail(request); LogIncomingInDetail(request);
} }
private void LogIncomingToContentTypeHandler(OSHttpRequest request) private void LogIncomingToContentTypeHandler(OSHttpRequest request)
{ {
m_log.DebugFormat( m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}",
request.ContentType, request.HttpMethod, request.Url.PathAndQuery); request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint);
if (DebugLevel >= 4) if (DebugLevel >= 5)
LogIncomingInDetail(request); LogIncomingInDetail(request);
} }
private void LogIncomingToXmlRpcHandler(OSHttpRequest request) private void LogIncomingToXmlRpcHandler(OSHttpRequest request)
{ {
m_log.DebugFormat( m_log.DebugFormat(
"[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1}", "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1} from {2}",
request.HttpMethod, request.Url.PathAndQuery); request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint);
if (DebugLevel >= 4) if (DebugLevel >= 5)
LogIncomingInDetail(request); LogIncomingInDetail(request);
} }
@ -682,7 +699,7 @@ namespace OpenSim.Framework.Servers.HttpServer
{ {
string output; string output;
if (DebugLevel == 4) if (DebugLevel == 5)
{ {
const int sampleLength = 80; const int sampleLength = 80;
char[] sampleChars = new char[sampleLength]; char[] sampleChars = new char[sampleLength];

48
OpenSim/Framework/Servers/MainServer.cs
View File

@ -51,8 +51,9 @@ namespace OpenSim.Framework.Servers
/// If DebugLevel >= 1 then short warnings are logged when receiving bad input data. /// If DebugLevel >= 1 then short warnings are logged when receiving bad input data.
/// If DebugLevel >= 2 then long warnings are logged when receiving bad input data. /// If DebugLevel >= 2 then long warnings are logged when receiving bad input data.
/// If DebugLevel >= 3 then short notices about all incoming non-poll HTTP requests are logged. /// If DebugLevel >= 3 then short notices about all incoming non-poll HTTP requests are logged.
/// If DebugLevel >= 4 then the start of the body of incoming non-poll HTTP requests will be logged. /// If DebugLevel >= 4 then the time taken to fulfill the request is logged.
/// If DebugLevel >= 5 then the entire body of incoming non-poll HTTP requests will be logged. /// If DebugLevel >= 5 then the start of the body of incoming non-poll HTTP requests will be logged.
/// If DebugLevel >= 6 then the entire body of incoming non-poll HTTP requests will be logged.
/// </remarks> /// </remarks>
public static int DebugLevel public static int DebugLevel
{ {
@ -115,15 +116,17 @@ namespace OpenSim.Framework.Servers
"Debug", false, "debug http", "debug http <in|out|all> [<level>]", "Debug", false, "debug http", "debug http <in|out|all> [<level>]",
"Turn on http request logging.", "Turn on http request logging.",
"If in or all and\n" "If in or all and\n"
+ " level <= 0, then no extra logging is done.\n" + " level <= 0 then no extra logging is done.\n"
+ " level >= 1, then short warnings are logged when receiving bad input data.\n" + " level >= 1 then short warnings are logged when receiving bad input data.\n"
+ " level >= 2, then long warnings are logged when receiving bad input data.\n" + " level >= 2 then long warnings are logged when receiving bad input data.\n"
+ " level >= 3, then short notices about all incoming non-poll HTTP requests are logged.\n" + " level >= 3 then short notices about all incoming non-poll HTTP requests are logged.\n"
+ " level >= 4, then a sample from the beginning of the incoming data is logged.\n" + " level >= 4 then the time taken to fulfill the request is logged.\n"
+ " level >= 5, then the entire incoming data is logged.\n" + " level >= 5 then a sample from the beginning of the incoming data is logged.\n"
+ " level >= 6 then the entire incoming data is logged.\n"
+ " no level is specified then the current level is returned.\n\n" + " no level is specified then the current level is returned.\n\n"
+ "If out or all and\n" + "If out or all and\n"
+ " level >= 3. then short notices about all outgoing requests going through WebUtil are logged.\n", + " level >= 3 then short notices about all outgoing requests going through WebUtil are logged.\n"
+ " level >= 4 then the time taken to fulfill the request is logged.\n",
HandleDebugHttpCommand); HandleDebugHttpCommand);
} }
@ -135,7 +138,7 @@ namespace OpenSim.Framework.Servers
{ {
if (cmdparams.Length < 3) if (cmdparams.Length < 3)
{ {
MainConsole.Instance.Output("Usage: debug http <in|out|all> 0..5"); MainConsole.Instance.Output("Usage: debug http <in|out|all> 0..6");
return; return;
} }
@ -145,12 +148,23 @@ namespace OpenSim.Framework.Servers
string subCommand = cmdparams[2]; string subCommand = cmdparams[2];
if (subCommand == "in") if (subCommand.ToLower() == "in")
{
inReqs = true; inReqs = true;
else if (subCommand == "out") }
else if (subCommand.ToLower() == "out")
{
outReqs = true; outReqs = true;
else }
else if (subCommand.ToLower() == "all")
{
allReqs = true; allReqs = true;
}
else
{
MainConsole.Instance.Output("You must specify in, out or all");
return;
}
if (cmdparams.Length >= 4) if (cmdparams.Length >= 4)
{ {
@ -172,22 +186,22 @@ namespace OpenSim.Framework.Servers
if (allReqs || inReqs) if (allReqs || inReqs)
{ {
MainServer.DebugLevel = newDebug; MainServer.DebugLevel = newDebug;
MainConsole.Instance.OutputFormat("In debug level set to {0}", newDebug); MainConsole.Instance.OutputFormat("IN debug level set to {0}", newDebug);
} }
if (allReqs || outReqs) if (allReqs || outReqs)
{ {
WebUtil.DebugLevel = newDebug; WebUtil.DebugLevel = newDebug;
MainConsole.Instance.OutputFormat("Out debug level set to {0}", newDebug); MainConsole.Instance.OutputFormat("OUT debug level set to {0}", newDebug);
} }
} }
else else
{ {
if (allReqs || inReqs) if (allReqs || inReqs)
MainConsole.Instance.OutputFormat("Current in debug level is {0}", MainServer.DebugLevel); MainConsole.Instance.OutputFormat("Current IN debug level is {0}", MainServer.DebugLevel);
if (allReqs || outReqs) if (allReqs || outReqs)
MainConsole.Instance.OutputFormat("Current out debug level is {0}", WebUtil.DebugLevel); MainConsole.Instance.OutputFormat("Current OUT debug level is {0}", WebUtil.DebugLevel);
} }
} }

24
OpenSim/Framework/WebUtil.cs
View File

@ -250,6 +250,10 @@ namespace OpenSim.Framework
strBuffer != null strBuffer != null
? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer) ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer)
: ""); : "");
else if (DebugLevel >= 4)
m_log.DebugFormat(
"[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
} }
m_log.DebugFormat( m_log.DebugFormat(
@ -405,6 +409,10 @@ namespace OpenSim.Framework
queryString != null queryString != null
? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString
: ""); : "");
else if (DebugLevel >= 4)
m_log.DebugFormat(
"[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
} }
m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage); m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
@ -879,6 +887,12 @@ namespace OpenSim.Framework
tickdata, tickdata,
originalRequest); originalRequest);
} }
else if (WebUtil.DebugLevel >= 4)
{
m_log.DebugFormat(
"[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
} }
} }
@ -995,6 +1009,10 @@ namespace OpenSim.Framework
tickdiff, tickdiff,
tickdata, tickdata,
obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj); obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj);
else if (WebUtil.DebugLevel >= 4)
m_log.DebugFormat(
"[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
return respstring; return respstring;
} }
@ -1144,6 +1162,12 @@ namespace OpenSim.Framework
tickdata, tickdata,
originalRequest); originalRequest);
} }
else if (WebUtil.DebugLevel >= 4)
{
m_log.DebugFormat(
"[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
return deserial; return deserial;
} }