diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index d2aa538ce1..478d2a7ef2 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -53,19 +53,36 @@ namespace OpenSim.Framework
LogManager.GetLogger(
MethodBase.GetCurrentMethod().DeclaringType);
- private static int m_requestNumber = 0;
+ ///
+ /// Request number for diagnostic purposes.
+ ///
+ public static int RequestNumber = 0;
- // this is the header field used to communicate the local request id
- // used for performance and debugging
+ ///
+ /// this is the header field used to communicate the local request id
+ /// used for performance and debugging
+ ///
public const string OSHeaderRequestID = "opensim-request-id";
- // number of milliseconds a call can take before it is considered
- // a "long" call for warning & debugging purposes
+ ///
+ /// Number of milliseconds a call can take before it is considered
+ /// a "long" call for warning & debugging purposes
+ ///
public const int LongCallTime = 500;
- // dictionary of end points
+ ///
+ /// The maximum length of any data logged because of a long request time.
+ ///
+ ///
+ /// This is to truncate any really large post data, such as an asset. In theory, the first section should
+ /// give us useful information about the call (which agent it relates to if applicable, etc.).
+ ///
+ public const int MaxRequestDiagLength = 100;
+
+ ///
+ /// Dictionary of end points
+ ///
private static Dictionary m_endpointSerializer = new Dictionary();
-
private static object EndPointLock(string url)
{
@@ -128,12 +145,13 @@ namespace OpenSim.Framework
private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
{
- int reqnum = m_requestNumber++;
+ int reqnum = RequestNumber++;
// m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
string errorMessage = "unknown error";
int tickstart = Util.EnvironmentTickCount();
int tickdata = 0;
+ string strBuffer = null;
try
{
@@ -148,7 +166,7 @@ namespace OpenSim.Framework
// If there is some input, write it into the request
if (data != null)
{
- string strBuffer = OSDParser.SerializeJsonString(data);
+ strBuffer = OSDParser.SerializeJsonString(data);
byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer);
if (compressed)
@@ -208,11 +226,18 @@ namespace OpenSim.Framework
}
finally
{
- // This just dumps a warning for any operation that takes more than 100 ms
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > LongCallTime)
- m_log.DebugFormat("[WEB UTIL]: osd request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
- reqnum,url,method,tickdiff,tickdata);
+ m_log.InfoFormat(
+ "[OSD REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+ reqnum,
+ method,
+ url,
+ tickdiff,
+ tickdata,
+ strBuffer != null
+ ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer)
+ : "");
}
m_log.DebugFormat(
@@ -290,17 +315,17 @@ namespace OpenSim.Framework
private static OSDMap ServiceFormRequestWorker(string url, NameValueCollection data, int timeout)
{
- int reqnum = m_requestNumber++;
+ int reqnum = RequestNumber++;
string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown";
// m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
string errorMessage = "unknown error";
int tickstart = Util.EnvironmentTickCount();
int tickdata = 0;
+ string queryString = null;
try
{
-
HttpWebRequest request = (HttpWebRequest)HttpWebRequest.Create(url);
request.Method = "POST";
request.Timeout = timeout;
@@ -311,7 +336,7 @@ namespace OpenSim.Framework
if (data != null)
{
- string queryString = BuildQueryString(data);
+ queryString = BuildQueryString(data);
byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString);
request.ContentLength = buffer.Length;
@@ -354,11 +379,19 @@ namespace OpenSim.Framework
{
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > LongCallTime)
- m_log.InfoFormat("[WEB UTIL]: form request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
- reqnum,url,method,tickdiff,tickdata);
+ m_log.InfoFormat(
+ "[SERVICE FORM]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+ reqnum,
+ method,
+ url,
+ tickdiff,
+ tickdata,
+ queryString != null
+ ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString
+ : "");
}
- m_log.WarnFormat("[WEB UTIL]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
+ m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
return ErrorResponseMap(errorMessage);
}
@@ -639,8 +672,6 @@ namespace OpenSim.Framework
return new string[0];
}
-
-
}
public static class AsynchronousRestObjectRequester
@@ -663,6 +694,12 @@ namespace OpenSim.Framework
public static void MakeRequest(string verb,
string requestUrl, TRequest obj, Action action)
{
+ int reqnum = WebUtil.RequestNumber++;
+ // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+ int tickstart = Util.EnvironmentTickCount();
+ int tickdata = 0;
+
// m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} {1}", verb, requestUrl);
Type type = typeof(TRequest);
@@ -673,12 +710,13 @@ namespace OpenSim.Framework
XmlSerializer deserializer = new XmlSerializer(typeof(TResponse));
request.Method = verb;
+ MemoryStream buffer = null;
if (verb == "POST")
{
request.ContentType = "text/xml";
- MemoryStream buffer = new MemoryStream();
+ buffer = new MemoryStream();
XmlWriterSettings settings = new XmlWriterSettings();
settings.Encoding = Encoding.UTF8;
@@ -700,6 +738,9 @@ namespace OpenSim.Framework
requestStream.Write(buffer.ToArray(), 0, length);
requestStream.Close();
+ // capture how much time was spent writing
+ tickdata = Util.EnvironmentTickCountSubtract(tickstart);
+
request.BeginGetResponse(delegate(IAsyncResult ar)
{
response = request.EndGetResponse(ar);
@@ -725,88 +766,108 @@ namespace OpenSim.Framework
}, null);
}, null);
-
-
- return;
}
-
- request.BeginGetResponse(delegate(IAsyncResult res2)
+ else
{
- try
+ request.BeginGetResponse(delegate(IAsyncResult res2)
{
- // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
- // documented in MSDN
- response = request.EndGetResponse(res2);
-
- Stream respStream = null;
try
{
- respStream = response.GetResponseStream();
- deserial = (TResponse)deserializer.Deserialize(respStream);
- }
- catch (System.InvalidOperationException)
- {
- }
- finally
- {
- respStream.Close();
- response.Close();
- }
- }
- catch (WebException e)
- {
- if (e.Status == WebExceptionStatus.ProtocolError)
- {
- if (e.Response is HttpWebResponse)
+ // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
+ // documented in MSDN
+ response = request.EndGetResponse(res2);
+
+ Stream respStream = null;
+ try
{
- HttpWebResponse httpResponse = (HttpWebResponse)e.Response;
-
- if (httpResponse.StatusCode != HttpStatusCode.NotFound)
- {
- // We don't appear to be handling any other status codes, so log these feailures to that
- // people don't spend unnecessary hours hunting phantom bugs.
- m_log.DebugFormat(
- "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}",
- verb, requestUrl, httpResponse.StatusCode);
- }
+ respStream = response.GetResponseStream();
+ deserial = (TResponse)deserializer.Deserialize(respStream);
+ }
+ catch (System.InvalidOperationException)
+ {
+ }
+ finally
+ {
+ respStream.Close();
+ response.Close();
}
}
- else
+ catch (WebException e)
+ {
+ if (e.Status == WebExceptionStatus.ProtocolError)
+ {
+ if (e.Response is HttpWebResponse)
+ {
+ HttpWebResponse httpResponse = (HttpWebResponse)e.Response;
+
+ if (httpResponse.StatusCode != HttpStatusCode.NotFound)
+ {
+ // We don't appear to be handling any other status codes, so log these feailures to that
+ // people don't spend unnecessary hours hunting phantom bugs.
+ m_log.DebugFormat(
+ "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}",
+ verb, requestUrl, httpResponse.StatusCode);
+ }
+ }
+ }
+ else
+ {
+ m_log.ErrorFormat(
+ "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}",
+ verb, requestUrl, e.Status, e.Message);
+ }
+ }
+ catch (Exception e)
{
m_log.ErrorFormat(
- "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}",
- verb, requestUrl, e.Status, e.Message);
+ "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}",
+ verb, requestUrl, e.Message, e.StackTrace);
}
- }
- catch (Exception e)
+
+ // m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString());
+
+ try
+ {
+ action(deserial);
+ }
+ catch (Exception e)
+ {
+ m_log.ErrorFormat(
+ "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}",
+ verb, requestUrl, e.Message, e.StackTrace);
+ }
+
+ }, null);
+ }
+
+ int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+ if (tickdiff > WebUtil.LongCallTime)
+ {
+ string originalRequest = null;
+
+ if (buffer != null)
{
- m_log.ErrorFormat(
- "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}",
- verb, requestUrl, e.Message, e.StackTrace);
+ originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
+
+ if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
+ originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
}
- // m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString());
-
- try
- {
- action(deserial);
- }
- catch (Exception e)
- {
- m_log.ErrorFormat(
- "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}",
- verb, requestUrl, e.Message, e.StackTrace);
- }
-
- }, null);
+ m_log.InfoFormat(
+ "[ASYNC REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+ reqnum,
+ verb,
+ requestUrl,
+ tickdiff,
+ tickdata,
+ originalRequest);
+ }
}
}
public static class SynchronousRestFormsRequester
{
- private static readonly ILog m_log =
- LogManager.GetLogger(
- MethodBase.GetCurrentMethod().DeclaringType);
+ private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
///
/// Perform a synchronous REST request.
@@ -820,6 +881,12 @@ namespace OpenSim.Framework
/// the request. You'll want to make sure you deal with this as they're not uncommon
public static string MakeRequest(string verb, string requestUrl, string obj)
{
+ int reqnum = WebUtil.RequestNumber++;
+ // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+ int tickstart = Util.EnvironmentTickCount();
+ int tickdata = 0;
+
WebRequest request = WebRequest.Create(requestUrl);
request.Method = verb;
string respstring = String.Empty;
@@ -855,6 +922,9 @@ namespace OpenSim.Framework
{
if (requestStream != null)
requestStream.Close();
+
+ // capture how much time was spent writing
+ tickdata = Util.EnvironmentTickCountSubtract(tickstart);
}
}
@@ -893,6 +963,18 @@ namespace OpenSim.Framework
m_log.DebugFormat("[FORMS]: InvalidOperationException on receiving {0} {1}", verb, requestUrl);
}
}
+
+ int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+ if (tickdiff > WebUtil.LongCallTime)
+ m_log.InfoFormat(
+ "[FORMS]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+ reqnum,
+ verb,
+ requestUrl,
+ tickdiff,
+ tickdata,
+ obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj);
+
return respstring;
}
}
@@ -915,17 +997,24 @@ namespace OpenSim.Framework
/// the request. You'll want to make sure you deal with this as they're not uncommon
public static TResponse MakeRequest(string verb, string requestUrl, TRequest obj)
{
+ int reqnum = WebUtil.RequestNumber++;
+ // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+ int tickstart = Util.EnvironmentTickCount();
+ int tickdata = 0;
+
Type type = typeof(TRequest);
TResponse deserial = default(TResponse);
WebRequest request = WebRequest.Create(requestUrl);
request.Method = verb;
+ MemoryStream buffer = null;
if ((verb == "POST") || (verb == "PUT"))
{
request.ContentType = "text/xml";
- MemoryStream buffer = new MemoryStream();
+ buffer = new MemoryStream();
XmlWriterSettings settings = new XmlWriterSettings();
settings.Encoding = Encoding.UTF8;
@@ -958,6 +1047,9 @@ namespace OpenSim.Framework
{
if (requestStream != null)
requestStream.Close();
+
+ // capture how much time was spent writing
+ tickdata = Util.EnvironmentTickCountSubtract(tickstart);
}
}
@@ -1005,6 +1097,29 @@ namespace OpenSim.Framework
verb, requestUrl, e.Message, e.StackTrace);
}
+ int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+ if (tickdiff > WebUtil.LongCallTime)
+ {
+ string originalRequest = null;
+
+ if (buffer != null)
+ {
+ originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
+
+ if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
+ originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
+ }
+
+ m_log.InfoFormat(
+ "[SynchronousRestObjectRequester]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
+ reqnum,
+ verb,
+ requestUrl,
+ tickdiff,
+ tickdata,
+ originalRequest);
+ }
+
return deserial;
}
}