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 --- .../Framework/Servers/HttpServer/BaseHttpServer.cs | 2 +- OpenSim/Framework/WebUtil.cs | 212 ++++++++++++++------- OpenSim/Services/Interfaces/OpenProfileClient.cs | 69 +------ prebuild.xml | 2 +- 4 files changed, 146 insertions(+), 139 deletions(-) diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs index 4f71db9..e8aa278 100644 --- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs +++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs @@ -705,7 +705,7 @@ namespace OpenSim.Framework.Servers.HttpServer } } - WebUtil.LogResponseDetail(output); + WebUtil.LogResponseDetail(null, output); } if (!response.SendChunked && response.ContentLength64 <= 0) 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); + } + } + } + + } } diff --git a/OpenSim/Services/Interfaces/OpenProfileClient.cs b/OpenSim/Services/Interfaces/OpenProfileClient.cs index 099b0c3..4126c35 100644 --- a/OpenSim/Services/Interfaces/OpenProfileClient.cs +++ b/OpenSim/Services/Interfaces/OpenProfileClient.cs @@ -35,7 +35,6 @@ using System.Reflection; using System.Text; using System.Xml; using log4net; -using Nwc.XmlRpc; using OpenMetaverse; using OpenSim.Framework; @@ -79,7 +78,12 @@ namespace OpenSim.Services.UserProfilesService Hashtable ReqHash = new Hashtable(); ReqHash["avatar_id"] = props.UserId.ToString(); - Hashtable profileData = GenericXMLRPCRequest(ReqHash, "avatar_properties_request", m_serverURI); + Hashtable profileData = XMLRPCRequester.SendRequest(ReqHash, "avatar_properties_request", m_serverURI); + + if (profileData == null) + return false; + if (!profileData.ContainsKey("data")) + return false; ArrayList dataArray = (ArrayList)profileData["data"]; @@ -128,66 +132,5 @@ namespace OpenSim.Services.UserProfilesService return true; } - - private Hashtable GenericXMLRPCRequest(Hashtable ReqParams, string method, string server) - { - ArrayList SendParams = new ArrayList(); - SendParams.Add(ReqParams); - - XmlRpcResponse Resp; - try - { - XmlRpcRequest Req = new XmlRpcRequest(method, SendParams); - Resp = Req.Send(server, 30000); - } - catch (WebException ex) - { - m_log.ErrorFormat("[PROFILE]: Unable to connect to Profile " + - "Server {0}. Exception {1}", server, ex); - - Hashtable ErrorHash = new Hashtable(); - ErrorHash["success"] = false; - ErrorHash["errorMessage"] = "Unable to fetch profile data at this time. "; - ErrorHash["errorURI"] = ""; - - return ErrorHash; - } - catch (SocketException ex) - { - m_log.ErrorFormat( - "[PROFILE]: Unable to connect to Profile Server {0}. Method {1}, params {2}. " + - "Exception {3}", server, method, ReqParams, ex); - - Hashtable ErrorHash = new Hashtable(); - ErrorHash["success"] = false; - ErrorHash["errorMessage"] = "Unable to fetch profile data at this time. "; - ErrorHash["errorURI"] = ""; - - return ErrorHash; - } - catch (XmlException ex) - { - m_log.ErrorFormat( - "[PROFILE]: Unable to connect to Profile Server {0}. Method {1}, params {2}. " + - "Exception {3}", server, method, ReqParams.ToString(), ex); - Hashtable ErrorHash = new Hashtable(); - ErrorHash["success"] = false; - ErrorHash["errorMessage"] = "Unable to fetch profile data at this time. "; - ErrorHash["errorURI"] = ""; - - return ErrorHash; - } - if (Resp.IsFault) - { - Hashtable ErrorHash = new Hashtable(); - ErrorHash["success"] = false; - ErrorHash["errorMessage"] = "Unable to fetch profile data at this time. "; - ErrorHash["errorURI"] = ""; - return ErrorHash; - } - Hashtable RespData = (Hashtable)Resp.Value; - - return RespData; - } } } diff --git a/prebuild.xml b/prebuild.xml index 577251b..9a419eb 100644 --- a/prebuild.xml +++ b/prebuild.xml @@ -93,6 +93,7 @@ + @@ -134,7 +135,6 @@ - -- cgit v1.1