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

- 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
0.8.0.3
Oren Hurvitz 2014-04-24 14:21:05 +03:00
parent e8a2eff2e8
commit bc06db3df4
4 changed files with 146 additions and 139 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -705,7 +705,7 @@ namespace OpenSim.Framework.Servers.HttpServer
}
}
WebUtil.LogResponseDetail(output);
WebUtil.LogResponseDetail(null, output);
}
if (!response.SendChunked && response.ContentLength64 <= 0)

212
OpenSim/Framework/WebUtil.cs
View File

@ -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);
}
}
}
}
}

69
OpenSim/Services/Interfaces/OpenProfileClient.cs
View File

@ -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;
}
}
}

2
prebuild.xml
View File

@ -93,6 +93,7 @@
<Reference name="System"/>
<Reference name="System.Core"/>
<Reference name="System.Xml"/>
<Reference name="System.Xml.Linq"/>
<Reference name="System.Data"/>
<Reference name="System.Drawing"/>
<Reference name="System.Web"/>
@ -134,7 +135,6 @@
<Reference name="OpenSim.Framework.Console"/>
<Reference name="OpenSim.Framework.Servers.HttpServer"/>
<Reference name="System.Xml"/>
<Reference name="XMLRPC" path="../../bin/"/>
<Reference name="Nini" path="../../../bin/"/>
<Reference name="log4net" path="../../../bin/"/>