From d15a3b10a3031b9552d67d2e2d435a689b448e2f Mon Sep 17 00:00:00 2001 From: Oren Hurvitz Date: Thu, 24 Apr 2014 14:19:03 +0300 Subject: When sending JSON-RPC calls (for UserProfile), use WebUtil instead of constructing the HTTP requests manually. This allows the calls to be logged when using "debug http all 6". --- OpenSim/Framework/WebUtil.cs | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) (limited to 'OpenSim/Framework/WebUtil.cs') diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs index 768ff16..8f5bc0c 100644 --- a/OpenSim/Framework/WebUtil.cs +++ b/OpenSim/Framework/WebUtil.cs @@ -127,41 +127,41 @@ namespace OpenSim.Framework /// public static OSDMap PutToServiceCompressed(string url, OSDMap data, int timeout) { - return ServiceOSDRequest(url,data, "PUT", timeout, true); + return ServiceOSDRequest(url,data, "PUT", timeout, true, false); } public static OSDMap PutToService(string url, OSDMap data, int timeout) { - return ServiceOSDRequest(url,data, "PUT", timeout, false); + return ServiceOSDRequest(url,data, "PUT", timeout, false, false); } - public static OSDMap PostToService(string url, OSDMap data, int timeout) + public static OSDMap PostToService(string url, OSDMap data, int timeout, bool rpc) { - return ServiceOSDRequest(url, data, "POST", timeout, false); + return ServiceOSDRequest(url, data, "POST", timeout, false, rpc); } public static OSDMap PostToServiceCompressed(string url, OSDMap data, int timeout) { - return ServiceOSDRequest(url, data, "POST", timeout, true); + return ServiceOSDRequest(url, data, "POST", timeout, true, false); } public static OSDMap GetFromService(string url, int timeout) { - return ServiceOSDRequest(url, null, "GET", timeout, false); + return ServiceOSDRequest(url, null, "GET", timeout, false, false); } - - public static OSDMap ServiceOSDRequest(string url, OSDMap data, string method, int timeout, bool compressed) + + public static OSDMap ServiceOSDRequest(string url, OSDMap data, string method, int timeout, bool compressed, bool rpc) { if (SerializeOSDRequestsPerEndpoint) { lock (EndPointLock(url)) { - return ServiceOSDRequestWorker(url, data, method, timeout, compressed); + return ServiceOSDRequestWorker(url, data, method, timeout, compressed, rpc); } } else { - return ServiceOSDRequestWorker(url, data, method, timeout, compressed); + return ServiceOSDRequestWorker(url, data, method, timeout, compressed, rpc); } } @@ -217,7 +217,7 @@ namespace OpenSim.Framework LogOutgoingDetail("RESPONSE: ", input); } - private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed) + private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed, bool rpc) { int reqnum = RequestNumber++; @@ -251,7 +251,7 @@ namespace OpenSim.Framework byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer); - request.ContentType = "application/json"; + request.ContentType = rpc ? "application/json-rpc" : "application/json"; if (compressed) { -- cgit v1.1 From bc06db3df45d8dd61338c5b1426fd0161731f7cd Mon Sep 17 00:00:00 2001 From: Oren Hurvitz Date: Thu, 24 Apr 2014 14:21:05 +0300 Subject: - Created a standard function to send XML-RPC requests, which logs them like we do for other types of HTTP activity. - Changed OpenProfileClient to use the new XML-RPC sending function - Improved logging in WebUtil --- OpenSim/Framework/WebUtil.cs | 212 ++++++++++++++++++++++++++++--------------- 1 file changed, 138 insertions(+), 74 deletions(-) (limited to 'OpenSim/Framework/WebUtil.cs') diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs index 8f5bc0c..d7f6bc8 100644 --- a/OpenSim/Framework/WebUtil.cs +++ b/OpenSim/Framework/WebUtil.cs @@ -39,7 +39,9 @@ using System.Text; using System.Web; using System.Xml; using System.Xml.Serialization; +using System.Xml.Linq; using log4net; +using Nwc.XmlRpc; using OpenMetaverse.StructuredData; using XMLResponseHelper = OpenSim.Framework.SynchronousRestObjectRequester.XMLResponseHelper; @@ -191,9 +193,9 @@ namespace OpenSim.Framework } } - public static void LogOutgoingDetail(string output) + public static void LogOutgoingDetail(string type, int reqnum, string output) { - LogOutgoingDetail("", output); + LogOutgoingDetail(string.Format("{0} {1}: ", type, reqnum), output); } public static void LogOutgoingDetail(string context, string output) @@ -207,14 +209,15 @@ namespace OpenSim.Framework m_log.DebugFormat("[LOGHTTP]: {0}{1}", context, Util.BinaryToASCII(output)); } - public static void LogResponseDetail(Stream inputStream) + public static void LogResponseDetail(int reqnum, Stream inputStream) { - LogOutgoingDetail("RESPONSE: ", inputStream); + LogOutgoingDetail(string.Format("RESPONSE {0}: ", reqnum), inputStream); } - public static void LogResponseDetail(string input) + public static void LogResponseDetail(int? reqnum, string input) { - LogOutgoingDetail("RESPONSE: ", input); + string context = (reqnum == null) ? "" : string.Format("RESPONSE {0}: ", reqnum.Value); + LogOutgoingDetail(context, input); } private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed, bool rpc) @@ -222,9 +225,8 @@ namespace OpenSim.Framework int reqnum = RequestNumber++; if (DebugLevel >= 3) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})", - reqnum, method, url, timeout, compressed); + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} JSON-RPC {1} to {2}", + reqnum, method, url); string errorMessage = "unknown error"; int tickstart = Util.EnvironmentTickCount(); @@ -247,7 +249,7 @@ namespace OpenSim.Framework strBuffer = OSDParser.SerializeJsonString(data); if (DebugLevel >= 5) - LogOutgoingDetail(strBuffer); + LogOutgoingDetail("SEND", reqnum, strBuffer); byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer); @@ -291,9 +293,8 @@ namespace OpenSim.Framework using (StreamReader reader = new StreamReader(responseStream)) { string responseStr = reader.ReadToEnd(); - // m_log.DebugFormat("[LOGHTTP]: <{0}> response is <{1}>",reqnum,responseStr); if (WebUtil.DebugLevel >= 5) - WebUtil.LogResponseDetail(responseStr); + WebUtil.LogResponseDetail(reqnum, responseStr); return CanonicalizeResults(responseStr); } } @@ -316,24 +317,23 @@ namespace OpenSim.Framework { int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); if (tickdiff > LongCallTime) + { m_log.InfoFormat( - "[LOGHTTP]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}", - reqnum, - method, - url, - tickdiff, - tickdata, + "[LOGHTTP]: Slow JSON-RPC request {0} {1} to {2} took {3}ms, {4}ms writing, {5}", + reqnum, method, url, tickdiff, tickdata, strBuffer != null ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer) : ""); + } else if (DebugLevel >= 4) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", + { + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", reqnum, tickdiff, tickdata); + } } m_log.DebugFormat( - "[LOGHTTP]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage); + "[LOGHTTP]: JSON-RPC request {0} {1} to {2} FAILED: {3}", reqnum, method, url, errorMessage); return ErrorResponseMap(errorMessage); } @@ -411,9 +411,8 @@ namespace OpenSim.Framework string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown"; if (DebugLevel >= 3) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})", - reqnum, method, url, timeout); + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} ServiceForm '{1}' to {2}", + reqnum, method, url); string errorMessage = "unknown error"; int tickstart = Util.EnvironmentTickCount(); @@ -435,7 +434,7 @@ namespace OpenSim.Framework queryString = BuildQueryString(data); if (DebugLevel >= 5) - LogOutgoingDetail(queryString); + LogOutgoingDetail("SEND", reqnum, queryString); byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString); @@ -457,7 +456,7 @@ namespace OpenSim.Framework { string responseStr = reader.ReadToEnd(); if (WebUtil.DebugLevel >= 5) - WebUtil.LogResponseDetail(responseStr); + WebUtil.LogResponseDetail(reqnum, responseStr); OSD responseOSD = OSDParser.Deserialize(responseStr); if (responseOSD.Type == OSDType.Map) @@ -483,23 +482,22 @@ namespace OpenSim.Framework { int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); if (tickdiff > LongCallTime) + { m_log.InfoFormat( - "[LOGHTTP]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}", - reqnum, - method, - url, - tickdiff, - tickdata, + "[LOGHTTP]: Slow ServiceForm request {0} '{1}' to {2} took {3}ms, {4}ms writing, {5}", + reqnum, method, url, tickdiff, tickdata, queryString != null ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString : ""); + } else if (DebugLevel >= 4) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", + { + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", reqnum, tickdiff, tickdata); + } } - m_log.WarnFormat("[LOGHTTP]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage); + m_log.WarnFormat("[LOGHTTP]: ServiceForm request {0} '{1}' to {2} failed: {3}", reqnum, method, url, errorMessage); return ErrorResponseMap(errorMessage); } @@ -779,8 +777,7 @@ namespace OpenSim.Framework int reqnum = WebUtil.RequestNumber++; if (WebUtil.DebugLevel >= 3) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} AsynchronousRequestObject {1} {2}", + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} AsynchronousRequestObject {1} to {2}", reqnum, verb, requestUrl); int tickstart = Util.EnvironmentTickCount(); @@ -822,7 +819,7 @@ namespace OpenSim.Framework byte[] data = buffer.ToArray(); if (WebUtil.DebugLevel >= 5) - WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); + WebUtil.LogOutgoingDetail("SEND", reqnum, System.Text.Encoding.UTF8.GetString(data)); request.BeginGetRequestStream(delegate(IAsyncResult res) { @@ -840,7 +837,8 @@ namespace OpenSim.Framework { using (Stream respStream = response.GetResponseStream()) { - deserial = XMLResponseHelper.LogAndDeserialize(respStream, response.ContentLength); + deserial = XMLResponseHelper.LogAndDeserialize( + reqnum, respStream, response.ContentLength); } } catch (System.InvalidOperationException) @@ -867,7 +865,8 @@ namespace OpenSim.Framework { using (Stream respStream = response.GetResponseStream()) { - deserial = XMLResponseHelper.LogAndDeserialize(respStream, response.ContentLength); + deserial = XMLResponseHelper.LogAndDeserialize( + reqnum, respStream, response.ContentLength); } } catch (System.InvalidOperationException) @@ -938,18 +937,13 @@ namespace OpenSim.Framework } m_log.InfoFormat( - "[LOGHTTP]: [ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", - reqnum, - verb, - requestUrl, - tickdiff, - tickdata, + "[LOGHTTP]: Slow AsynchronousRequestObject request {0} {1} to {2} took {3}ms, {4}ms writing, {5}", + reqnum, verb, requestUrl, tickdiff, tickdata, originalRequest); } else if (WebUtil.DebugLevel >= 4) { - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", reqnum, tickdiff, tickdata); } } @@ -981,8 +975,7 @@ namespace OpenSim.Framework int reqnum = WebUtil.RequestNumber++; if (WebUtil.DebugLevel >= 3) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} SynchronousRestForms {1} {2}", + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} SynchronousRestForms {1} to {2}", reqnum, verb, requestUrl); int tickstart = Util.EnvironmentTickCount(); @@ -1012,7 +1005,7 @@ namespace OpenSim.Framework byte[] data = buffer.ToArray(); if (WebUtil.DebugLevel >= 5) - WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); + WebUtil.LogOutgoingDetail("SEND", reqnum, System.Text.Encoding.UTF8.GetString(data)); Stream requestStream = null; try @@ -1058,21 +1051,20 @@ namespace OpenSim.Framework int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); if (tickdiff > WebUtil.LongCallTime) + { m_log.InfoFormat( - "[LOGHTTP]: [FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", - reqnum, - verb, - requestUrl, - tickdiff, - tickdata, + "[LOGHTTP]: Slow SynchronousRestForms request {0} {1} to {2} took {3}ms, {4}ms writing, {5}", + reqnum, verb, requestUrl, tickdiff, tickdata, obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj); + } else if (WebUtil.DebugLevel >= 4) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", + { + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", reqnum, tickdiff, tickdata); + } if (WebUtil.DebugLevel >= 5) - WebUtil.LogResponseDetail(respstring); + WebUtil.LogResponseDetail(reqnum, respstring); return respstring; } @@ -1114,8 +1106,7 @@ namespace OpenSim.Framework int reqnum = WebUtil.RequestNumber++; if (WebUtil.DebugLevel >= 3) - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} SynchronousRestObject {1} {2}", + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} SynchronousRestObject {1} to {2}", reqnum, verb, requestUrl); int tickstart = Util.EnvironmentTickCount(); @@ -1155,7 +1146,7 @@ namespace OpenSim.Framework byte[] data = buffer.ToArray(); if (WebUtil.DebugLevel >= 5) - WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); + WebUtil.LogOutgoingDetail("SEND", reqnum, System.Text.Encoding.UTF8.GetString(data)); try { @@ -1185,7 +1176,8 @@ namespace OpenSim.Framework { using (Stream respStream = resp.GetResponseStream()) { - deserial = XMLResponseHelper.LogAndDeserialize(respStream, resp.ContentLength); + deserial = XMLResponseHelper.LogAndDeserialize( + reqnum, respStream, resp.ContentLength); } } else @@ -1236,18 +1228,13 @@ namespace OpenSim.Framework } m_log.InfoFormat( - "[LOGHTTP]: [SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", - reqnum, - verb, - requestUrl, - tickdiff, - tickdata, + "[LOGHTTP]: Slow SynchronousRestObject request {0} {1} to {2} took {3}ms, {4}ms writing, {5}", + reqnum, verb, requestUrl, tickdiff, tickdata, originalRequest); } else if (WebUtil.DebugLevel >= 4) { - m_log.DebugFormat( - "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", reqnum, tickdiff, tickdata); } } @@ -1263,7 +1250,7 @@ namespace OpenSim.Framework public static class XMLResponseHelper { - public static TResponse LogAndDeserialize(Stream respStream, long contentLength) + public static TResponse LogAndDeserialize(int reqnum, Stream respStream, long contentLength) { XmlSerializer deserializer = new XmlSerializer(typeof(TResponse)); @@ -1272,7 +1259,7 @@ namespace OpenSim.Framework byte[] data = new byte[contentLength]; Util.ReadStream(respStream, data); - WebUtil.LogResponseDetail(System.Text.Encoding.UTF8.GetString(data)); + WebUtil.LogResponseDetail(reqnum, System.Text.Encoding.UTF8.GetString(data)); using (MemoryStream temp = new MemoryStream(data)) return (TResponse)deserializer.Deserialize(temp); @@ -1284,4 +1271,81 @@ namespace OpenSim.Framework } } } + + + public static class XMLRPCRequester + { + private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); + + public static Hashtable SendRequest(Hashtable ReqParams, string method, string url) + { + int reqnum = WebUtil.RequestNumber++; + + if (WebUtil.DebugLevel >= 3) + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} XML-RPC '{1}' to {2}", + reqnum, method, url); + + int tickstart = Util.EnvironmentTickCount(); + string responseStr = null; + + try + { + ArrayList SendParams = new ArrayList(); + SendParams.Add(ReqParams); + + XmlRpcRequest Req = new XmlRpcRequest(method, SendParams); + + if (WebUtil.DebugLevel >= 5) + { + string str = Req.ToString(); + str = XElement.Parse(str).ToString(SaveOptions.DisableFormatting); + WebUtil.LogOutgoingDetail("SEND", reqnum, str); + } + + XmlRpcResponse Resp = Req.Send(url, 30000); + + try + { + responseStr = Resp.ToString(); + responseStr = XElement.Parse(responseStr).ToString(SaveOptions.DisableFormatting); + + if (WebUtil.DebugLevel >= 5) + WebUtil.LogResponseDetail(reqnum, responseStr); + } + catch (Exception e) + { + m_log.Error("Error parsing XML-RPC response", e); + } + + if (Resp.IsFault) + { + m_log.DebugFormat( + "[LOGHTTP]: XML-RPC request {0} '{1}' to {2} FAILED: FaultCode={3}, FaultMessage={4}", + reqnum, method, url, Resp.FaultCode, Resp.FaultString); + return null; + } + + Hashtable RespData = (Hashtable)Resp.Value; + return RespData; + } + finally + { + int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); + if (tickdiff > WebUtil.LongCallTime) + { + m_log.InfoFormat( + "[LOGHTTP]: Slow XML-RPC request {0} '{1}' to {2} took {3}ms, {4}", + reqnum, method, url, tickdiff, + responseStr != null + ? (responseStr.Length > WebUtil.MaxRequestDiagLength ? responseStr.Remove(WebUtil.MaxRequestDiagLength) : responseStr) + : ""); + } + else if (WebUtil.DebugLevel >= 4) + { + m_log.DebugFormat("[LOGHTTP]: HTTP OUT {0} took {1}ms", reqnum, tickdiff); + } + } + } + + } } -- cgit v1.1