From 387a1bb283c0c55178421f2c28b0d28a24dac7a1 Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Thu, 20 Sep 2012 22:36:47 +0100 Subject: Add ability to turn on/off logging of outgoing HTTP requests flowing through WebUtil. This is for debugging purposes. This is controlled via the "debug http" command which can already log incoming requests. This now gains a mandatory parameter of in, out or all to control what is logged. Log messages are also shortened and labelled and HTTP IN or HTTP OUT to be consistent with existing UDP PACKET IN and PACKET OUT messages. --- .../Framework/Servers/HttpServer/BaseHttpServer.cs | 10 +-- OpenSim/Framework/Servers/MainServer.cs | 87 ++++++++++++++++------ 2 files changed, 70 insertions(+), 27 deletions(-) (limited to 'OpenSim/Framework/Servers') diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs index 43a19fa..f93b3dd 100644 --- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs +++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs @@ -529,7 +529,7 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}", + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", request.ContentType, request.HttpMethod, request.Url.PathAndQuery); buffer = HandleHTTPRequest(request, response); @@ -541,7 +541,7 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}", + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", request.ContentType, request.HttpMethod, request.Url.PathAndQuery); buffer = HandleLLSDRequests(request, response); @@ -649,7 +649,7 @@ namespace OpenSim.Framework.Servers.HttpServer private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) { m_log.DebugFormat( - "[BASE HTTP SERVER]: Found stream handler for {0} {1} {2} {3}", + "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3}", request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description); if (DebugLevel >= 4) @@ -659,7 +659,7 @@ namespace OpenSim.Framework.Servers.HttpServer private void LogIncomingToContentTypeHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: Found a {0} content type handler for {1} {2}", + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", request.ContentType, request.HttpMethod, request.Url.PathAndQuery); if (DebugLevel >= 4) @@ -669,7 +669,7 @@ namespace OpenSim.Framework.Servers.HttpServer private void LogIncomingToXmlRpcHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: Assuming a generic XMLRPC request for {0} {1}", + "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1}", request.HttpMethod, request.Url.PathAndQuery); if (DebugLevel >= 4) diff --git a/OpenSim/Framework/Servers/MainServer.cs b/OpenSim/Framework/Servers/MainServer.cs index 7402c73..b7a133e 100644 --- a/OpenSim/Framework/Servers/MainServer.cs +++ b/OpenSim/Framework/Servers/MainServer.cs @@ -48,9 +48,11 @@ namespace OpenSim.Framework.Servers /// Control the printing of certain debug messages. /// /// - /// 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 >= 3, then short notices about all incoming non-poll HTTP requests are logged. + /// 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 >= 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 >= 5 then the entire body of incoming non-poll HTTP requests will be logged. /// public static int DebugLevel { @@ -102,7 +104,6 @@ namespace OpenSim.Framework.Servers get { return new Dictionary(m_Servers); } } - public static void RegisterHttpConsoleCommands(ICommandConsole console) { console.Commands.AddCommand( @@ -111,15 +112,18 @@ namespace OpenSim.Framework.Servers "Show all registered http handlers", HandleShowHttpHandlersCommand); console.Commands.AddCommand( - "Debug", false, "debug http", "debug http []", - "Turn on inbound non-poll http request debugging.", - "If level <= 0, then no extra logging is done.\n" - + "If level >= 1, then short warnings are logged when receiving bad input data.\n" - + "If level >= 2, then long warnings are logged when receiving bad input data.\n" - + "If level >= 3, then short notices about all incoming non-poll HTTP requests are logged.\n" - + "If level >= 4, then a sample from the beginning of the incoming data is logged.\n" - + "If level >= 5, then the entire incoming data is logged.\n" - + "If no level is specified then the current level is returned.", + "Debug", false, "debug http", "debug http []", + "Turn on http request logging.", + "If in or all and\n" + + " level <= 0, then no extra logging is done.\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 >= 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 >= 5, then the entire incoming data is logged.\n" + + " no level is specified then the current level is returned.\n\n" + + "If out or all and\n" + + " level >= 3. then short notices about all outgoing requests going through WebUtil are logged.\n", HandleDebugHttpCommand); } @@ -127,24 +131,63 @@ namespace OpenSim.Framework.Servers /// Turn on some debugging values for OpenSim. /// /// - private static void HandleDebugHttpCommand(string module, string[] args) + private static void HandleDebugHttpCommand(string module, string[] cmdparams) { - if (args.Length == 3) + if (cmdparams.Length < 3) { + MainConsole.Instance.Output("Usage: debug http 0..5"); + return; + } + + bool inReqs = false; + bool outReqs = false; + bool allReqs = false; + + string subCommand = cmdparams[2]; + + if (subCommand == "in") + inReqs = true; + else if (subCommand == "out") + outReqs = true; + else + allReqs = true; + + if (cmdparams.Length >= 4) + { + string rawNewDebug = cmdparams[3]; int newDebug; - if (int.TryParse(args[2], out newDebug)) + + if (!int.TryParse(rawNewDebug, out newDebug)) + { + MainConsole.Instance.OutputFormat("{0} is not a valid debug level", rawNewDebug); + return; + } + + if (newDebug < 0 || newDebug > 5) + { + MainConsole.Instance.OutputFormat("{0} is outside the valid debug level range of 0..5", newDebug); + return; + } + + if (allReqs || inReqs) { MainServer.DebugLevel = newDebug; - MainConsole.Instance.OutputFormat("Debug http level set to {0}", newDebug); + MainConsole.Instance.OutputFormat("In debug level set to {0}", newDebug); + } + + if (allReqs || outReqs) + { + WebUtil.DebugLevel = newDebug; + MainConsole.Instance.OutputFormat("Out debug level set to {0}", newDebug); } - } - else if (args.Length == 2) - { - MainConsole.Instance.OutputFormat("Current debug http level is {0}", MainServer.DebugLevel); } else { - MainConsole.Instance.Output("Usage: debug http 0..5"); + if (allReqs || inReqs) + MainConsole.Instance.OutputFormat("Current in debug level is {0}", MainServer.DebugLevel); + + if (allReqs || outReqs) + MainConsole.Instance.OutputFormat("Current out debug level is {0}", WebUtil.DebugLevel); } } -- cgit v1.1 From a5b3989e5db0a3b22e44b84412227a8e487bcef2 Mon Sep 17 00:00:00 2001 From: Justin Clark-Casey (justincc) Date: Thu, 20 Sep 2012 23:18:19 +0100 Subject: 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. --- .../Framework/Servers/HttpServer/BaseHttpServer.cs | 47 ++++++++++++++------- OpenSim/Framework/Servers/MainServer.cs | 48 ++++++++++++++-------- 2 files changed, 63 insertions(+), 32 deletions(-) (limited to 'OpenSim/Framework/Servers') diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs index f93b3dd..4e04dd8 100644 --- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs +++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs @@ -54,6 +54,12 @@ namespace OpenSim.Framework.Servers.HttpServer private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); private HttpServerLogWriter httpserverlog = new HttpServerLogWriter(); + /// + /// Gets or sets the debug level. + /// + /// + /// See MainServer.DebugLevel. + /// public int DebugLevel { get; set; } private volatile int NotSocketErrors = 0; @@ -529,8 +535,8 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); buffer = HandleHTTPRequest(request, response); break; @@ -541,8 +547,8 @@ namespace OpenSim.Framework.Servers.HttpServer if (DebugLevel >= 3) m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); buffer = HandleLLSDRequests(request, response); break; @@ -640,7 +646,18 @@ namespace OpenSim.Framework.Servers.HttpServer uriString, requestHandler != null ? requestHandler.Name : "", 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); } } @@ -649,30 +666,30 @@ namespace OpenSim.Framework.Servers.HttpServer private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3}", - request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description); + "[BASE HTTP SERVER]: HTTP IN stream handler {0} {1} {2} {3} from {4}", + request.HttpMethod, request.Url.PathAndQuery, requestHandler.Name, requestHandler.Description, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } private void LogIncomingToContentTypeHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2}", - request.ContentType, request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN {0} content type handler {1} {2} from {3}", + request.ContentType, request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } private void LogIncomingToXmlRpcHandler(OSHttpRequest request) { m_log.DebugFormat( - "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1}", - request.HttpMethod, request.Url.PathAndQuery); + "[BASE HTTP SERVER]: HTTP IN assumed generic XMLRPC request {0} {1} from {2}", + request.HttpMethod, request.Url.PathAndQuery, request.RemoteIPEndPoint); - if (DebugLevel >= 4) + if (DebugLevel >= 5) LogIncomingInDetail(request); } @@ -682,7 +699,7 @@ namespace OpenSim.Framework.Servers.HttpServer { string output; - if (DebugLevel == 4) + if (DebugLevel == 5) { const int sampleLength = 80; char[] sampleChars = new char[sampleLength]; diff --git a/OpenSim/Framework/Servers/MainServer.cs b/OpenSim/Framework/Servers/MainServer.cs index b7a133e..72f9cce 100644 --- a/OpenSim/Framework/Servers/MainServer.cs +++ b/OpenSim/Framework/Servers/MainServer.cs @@ -51,8 +51,9 @@ namespace OpenSim.Framework.Servers /// 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 >= 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 >= 5 then the entire 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 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. /// public static int DebugLevel { @@ -115,15 +116,17 @@ namespace OpenSim.Framework.Servers "Debug", false, "debug http", "debug http []", "Turn on http request logging.", "If in or all and\n" - + " level <= 0, then no extra logging is done.\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 >= 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 >= 5, then the entire incoming data is logged.\n" + + " level <= 0 then no extra logging is done.\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 >= 3 then short notices about all incoming non-poll HTTP requests are logged.\n" + + " level >= 4 then the time taken to fulfill the request 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" + "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); } @@ -135,7 +138,7 @@ namespace OpenSim.Framework.Servers { if (cmdparams.Length < 3) { - MainConsole.Instance.Output("Usage: debug http 0..5"); + MainConsole.Instance.Output("Usage: debug http 0..6"); return; } @@ -145,12 +148,23 @@ namespace OpenSim.Framework.Servers string subCommand = cmdparams[2]; - if (subCommand == "in") + if (subCommand.ToLower() == "in") + { inReqs = true; - else if (subCommand == "out") + } + else if (subCommand.ToLower() == "out") + { outReqs = true; - else + } + else if (subCommand.ToLower() == "all") + { allReqs = true; + } + else + { + MainConsole.Instance.Output("You must specify in, out or all"); + return; + } if (cmdparams.Length >= 4) { @@ -172,22 +186,22 @@ namespace OpenSim.Framework.Servers if (allReqs || inReqs) { 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) { WebUtil.DebugLevel = newDebug; - MainConsole.Instance.OutputFormat("Out debug level set to {0}", newDebug); + MainConsole.Instance.OutputFormat("OUT debug level set to {0}", newDebug); } } else { 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) - MainConsole.Instance.OutputFormat("Current out debug level is {0}", WebUtil.DebugLevel); + MainConsole.Instance.OutputFormat("Current OUT debug level is {0}", WebUtil.DebugLevel); } } -- cgit v1.1