- 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

3 files changed, 145 insertions, 138 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<TRequest, TResponse>(respStream, response.ContentLength);
+                                        deserial = XMLResponseHelper.LogAndDeserialize<TRequest, TResponse>(
+                                            reqnum, respStream, response.ContentLength);
                                     }
                                 }
                                 catch (System.InvalidOperationException)
@@ -867,7 +865,8 @@ namespace OpenSim.Framework
                                 {
                                     using (Stream respStream = response.GetResponseStream())
                                     {
-                                        deserial = XMLResponseHelper.LogAndDeserialize<TRequest, TResponse>(respStream, response.ContentLength);
+                                        deserial = XMLResponseHelper.LogAndDeserialize<TRequest, TResponse>(
+                                            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<TRequest, TResponse>(respStream, resp.ContentLength);
+                                deserial = XMLResponseHelper.LogAndDeserialize<TRequest, TResponse>(
+                                    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<TRequest, TResponse>(Stream respStream, long contentLength)
+            public static TResponse LogAndDeserialize<TRequest, TResponse>(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;
-        }
     }
 }