From f901a3820497e0d99accb6f5f60f6517e07c2c8f Mon Sep 17 00:00:00 2001
From: Oren Hurvitz
Date: Thu, 28 Nov 2013 23:07:14 +0200
Subject: Improved logging of HTTP requests - MemoryBuffer isn't seekable, so
we can't log it. Log the string instead. - Handle compressed streams - Don't
attempt to dump binary data. Either don't log it at all (if we know it's
binary), or at least convert non-ASCII characters to ASCII. - Log responses
to HTTP requests - Use the same log prefix for all of these log messages
("[LOGHTTP]"), to make them easy to see at a glance - Increased the snippet
length to 200 (80 doesn't show enough), and add "..." only if the message was
actually truncated
Resolves http://opensimulator.org/mantis/view.php?id=6949
---
.../Framework/Servers/HttpServer/BaseHttpServer.cs | 52 ++++++---
OpenSim/Framework/Util.cs | 40 +++++++
OpenSim/Framework/WebUtil.cs | 122 +++++++++++++++------
3 files changed, 165 insertions(+), 49 deletions(-)
(limited to 'OpenSim/Framework')
diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
index e243002..19231e1 100644
--- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
+++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
@@ -46,6 +46,7 @@ using CoolHTTPListener = HttpServer.HttpListener;
using HttpListener=System.Net.HttpListener;
using LogPrio=HttpServer.LogPrio;
using OpenSim.Framework.Monitoring;
+using System.IO.Compression;
namespace OpenSim.Framework.Servers.HttpServer
{
@@ -690,6 +691,23 @@ namespace OpenSim.Framework.Servers.HttpServer
if (buffer != null)
{
+ if (WebUtil.DebugLevel >= 5)
+ {
+ string output = System.Text.Encoding.UTF8.GetString(buffer);
+
+ if (WebUtil.DebugLevel >= 6)
+ {
+ // Always truncate binary blobs. We don't have a ContentType, so detect them using the request name.
+ if ((requestHandler != null && requestHandler.Name == "GetMesh"))
+ {
+ if (output.Length > WebUtil.MaxRequestDiagLength)
+ output = output.Substring(0, WebUtil.MaxRequestDiagLength) + "...";
+ }
+ }
+
+ WebUtil.LogResponseDetail(output);
+ }
+
if (!response.SendChunked && response.ContentLength64 <= 0)
response.ContentLength64 = buffer.LongLength;
@@ -743,7 +761,7 @@ namespace OpenSim.Framework.Servers.HttpServer
if (tickdiff > 3000 && requestHandler != null && requestHandler.Name != "GetTexture")
{
m_log.InfoFormat(
- "[BASE HTTP SERVER]: Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms",
+ "[LOGHTTP] Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms",
RequestNumber,
requestMethod,
uriString,
@@ -755,7 +773,7 @@ namespace OpenSim.Framework.Servers.HttpServer
else if (DebugLevel >= 4)
{
m_log.DebugFormat(
- "[BASE HTTP SERVER]: HTTP IN {0} :{1} took {2}ms",
+ "[LOGHTTP] HTTP IN {0} :{1} took {2}ms",
RequestNumber,
Port,
tickdiff);
@@ -766,7 +784,7 @@ namespace OpenSim.Framework.Servers.HttpServer
private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler)
{
m_log.DebugFormat(
- "[BASE HTTP SERVER]: HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}",
+ "[LOGHTTP] HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}",
RequestNumber,
Port,
request.HttpMethod,
@@ -782,7 +800,7 @@ namespace OpenSim.Framework.Servers.HttpServer
private void LogIncomingToContentTypeHandler(OSHttpRequest request)
{
m_log.DebugFormat(
- "[BASE HTTP SERVER]: HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}",
+ "[LOGHTTP] HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}",
RequestNumber,
Port,
string.IsNullOrEmpty(request.ContentType) ? "not set" : request.ContentType,
@@ -797,7 +815,7 @@ namespace OpenSim.Framework.Servers.HttpServer
private void LogIncomingToXmlRpcHandler(OSHttpRequest request)
{
m_log.DebugFormat(
- "[BASE HTTP SERVER]: HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}",
+ "[LOGHTTP] HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}",
RequestNumber,
Port,
request.HttpMethod,
@@ -810,26 +828,32 @@ namespace OpenSim.Framework.Servers.HttpServer
private void LogIncomingInDetail(OSHttpRequest request)
{
- using (StreamReader reader = new StreamReader(Util.Copy(request.InputStream), Encoding.UTF8))
+ if (request.ContentType == "application/octet-stream")
+ return; // never log these; they're just binary data
+
+ Stream inputStream = Util.Copy(request.InputStream);
+
+ if (request.ContentType == "application/x-gzip")
+ inputStream = new GZipStream(inputStream, System.IO.Compression.CompressionMode.Decompress);
+
+ using (StreamReader reader = new StreamReader(inputStream, Encoding.UTF8))
{
string output;
if (DebugLevel == 5)
{
- const int sampleLength = 80;
- char[] sampleChars = new char[sampleLength + 3];
- reader.Read(sampleChars, 0, sampleLength);
- sampleChars[80] = '.';
- sampleChars[81] = '.';
- sampleChars[82] = '.';
- output = new string(sampleChars);
+ char[] chars = new char[WebUtil.MaxRequestDiagLength + 1]; // +1 so we know to add "..." only if needed
+ int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1);
+ output = new string(chars, 0, Math.Min(len, WebUtil.MaxRequestDiagLength));
+ if (len > WebUtil.MaxRequestDiagLength)
+ output += "...";
}
else
{
output = reader.ReadToEnd();
}
- m_log.DebugFormat("[BASE HTTP SERVER]: {0}", output.Replace("\n", @"\n"));
+ m_log.DebugFormat("[LOGHTTP] {0}", Util.BinaryToASCII(output));
}
}
diff --git a/OpenSim/Framework/Util.cs b/OpenSim/Framework/Util.cs
index ae720f1..ce4af8b 100644
--- a/OpenSim/Framework/Util.cs
+++ b/OpenSim/Framework/Util.cs
@@ -1510,6 +1510,46 @@ namespace OpenSim.Framework
return result;
}
+ public static void BinaryToASCII(char[] chars)
+ {
+ for (int i = 0; i < chars.Length; i++)
+ {
+ char ch = chars[i];
+ if (ch < 32 || ch > 127)
+ chars[i] = '.';
+ }
+ }
+
+ public static string BinaryToASCII(string src)
+ {
+ char[] chars = src.ToCharArray();
+ BinaryToASCII(chars);
+ return new String(chars);
+ }
+
+ ///
+ /// Reads a known number of bytes from a stream.
+ /// Throws EndOfStreamException if the stream doesn't contain enough data.
+ ///
+ /// The stream to read data from
+ /// The array to write bytes into. The array
+ /// will be completely filled from the stream, so an appropriate
+ /// size must be given.
+ public static void ReadStream(Stream stream, byte[] data)
+ {
+ int offset = 0;
+ int remaining = data.Length;
+
+ while (remaining > 0)
+ {
+ int read = stream.Read(data, offset, remaining);
+ if (read <= 0)
+ throw new EndOfStreamException(String.Format("End of stream reached with {0} bytes left to read", remaining));
+ remaining -= read;
+ offset += read;
+ }
+ }
+
public static Guid GetHashGuid(string data, string salt)
{
byte[] hash = ComputeMD5Hash(data + salt);
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index c7f1bdb..7f341d2 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -89,8 +89,9 @@ namespace OpenSim.Framework
///
/// 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.).
+ /// This is also used to truncate messages when using DebugLevel 5.
///
- public const int MaxRequestDiagLength = 100;
+ public const int MaxRequestDiagLength = 200;
///
/// Dictionary of end points
@@ -165,35 +166,54 @@ namespace OpenSim.Framework
public static void LogOutgoingDetail(Stream outputStream)
{
+ LogOutgoingDetail("", outputStream);
+ }
+
+ public static void LogOutgoingDetail(string context, Stream outputStream)
+ {
using (StreamReader reader = new StreamReader(Util.Copy(outputStream), Encoding.UTF8))
{
string output;
if (DebugLevel == 5)
{
- const int sampleLength = 80;
- char[] sampleChars = new char[sampleLength];
- reader.Read(sampleChars, 0, sampleLength);
- output = new string(sampleChars);
+ char[] chars = new char[WebUtil.MaxRequestDiagLength + 1]; // +1 so we know to add "..." only if needed
+ int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1);
+ output = new string(chars, 0, len);
}
else
{
output = reader.ReadToEnd();
}
- LogOutgoingDetail(output);
+ LogOutgoingDetail(context, output);
}
}
public static void LogOutgoingDetail(string output)
{
+ LogOutgoingDetail("", output);
+ }
+
+ public static void LogOutgoingDetail(string context, string output)
+ {
if (DebugLevel == 5)
{
- output = output.Substring(0, 80);
- output = output + "...";
+ if (output.Length > MaxRequestDiagLength)
+ output = output.Substring(0, MaxRequestDiagLength) + "...";
}
- m_log.DebugFormat("[WEB UTIL]: {0}", output.Replace("\n", @"\n"));
+ m_log.DebugFormat("[LOGHTTP]: {0}{1}", context, Util.BinaryToASCII(output));
+ }
+
+ public static void LogResponseDetail(Stream inputStream)
+ {
+ LogOutgoingDetail("RESPONSE: ", inputStream);
+ }
+
+ public static void LogResponseDetail(string input)
+ {
+ LogOutgoingDetail("RESPONSE: ", input);
}
private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
@@ -202,7 +222,7 @@ namespace OpenSim.Framework
if (DebugLevel >= 3)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})",
+ "[LOGHTTP]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})",
reqnum, method, url, timeout, compressed);
string errorMessage = "unknown error";
@@ -268,7 +288,9 @@ namespace OpenSim.Framework
using (StreamReader reader = new StreamReader(responseStream))
{
string responseStr = reader.ReadToEnd();
- // m_log.DebugFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr);
+ // m_log.DebugFormat("[LOGHTTP]: <{0}> response is <{1}>",reqnum,responseStr);
+ if (WebUtil.DebugLevel >= 5)
+ WebUtil.LogResponseDetail(responseStr);
return CanonicalizeResults(responseStr);
}
}
@@ -292,7 +314,7 @@ namespace OpenSim.Framework
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > LongCallTime)
m_log.InfoFormat(
- "[WEB UTIL]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+ "[LOGHTTP]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
reqnum,
method,
url,
@@ -303,12 +325,12 @@ namespace OpenSim.Framework
: "");
else if (DebugLevel >= 4)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+ "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
m_log.DebugFormat(
- "[WEB UTIL]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage);
+ "[LOGHTTP]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage);
return ErrorResponseMap(errorMessage);
}
@@ -387,7 +409,7 @@ namespace OpenSim.Framework
if (DebugLevel >= 3)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})",
+ "[LOGHTTP]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})",
reqnum, method, url, timeout);
string errorMessage = "unknown error";
@@ -431,6 +453,8 @@ namespace OpenSim.Framework
using (StreamReader reader = new StreamReader(responseStream))
{
string responseStr = reader.ReadToEnd();
+ if (WebUtil.DebugLevel >= 5)
+ WebUtil.LogResponseDetail(responseStr);
OSD responseOSD = OSDParser.Deserialize(responseStr);
if (responseOSD.Type == OSDType.Map)
@@ -457,7 +481,7 @@ namespace OpenSim.Framework
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > LongCallTime)
m_log.InfoFormat(
- "[WEB UTIL]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+ "[LOGHTTP]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
reqnum,
method,
url,
@@ -468,11 +492,11 @@ namespace OpenSim.Framework
: "");
else if (DebugLevel >= 4)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+ "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
- m_log.WarnFormat("[WEB UTIL]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage);
+ m_log.WarnFormat("[LOGHTTP]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage);
return ErrorResponseMap(errorMessage);
}
@@ -753,7 +777,7 @@ namespace OpenSim.Framework
if (WebUtil.DebugLevel >= 3)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} AsynchronousRequestObject {1} {2}",
+ "[LOGHTTP]: HTTP OUT {0} AsynchronousRequestObject {1} {2}",
reqnum, verb, requestUrl);
int tickstart = Util.EnvironmentTickCount();
@@ -793,14 +817,15 @@ namespace OpenSim.Framework
int length = (int)buffer.Length;
request.ContentLength = length;
+ byte[] data = buffer.ToArray();
if (WebUtil.DebugLevel >= 5)
- WebUtil.LogOutgoingDetail(buffer);
+ WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
request.BeginGetRequestStream(delegate(IAsyncResult res)
{
using (Stream requestStream = request.EndGetRequestStream(res))
- requestStream.Write(buffer.ToArray(), 0, length);
+ requestStream.Write(data, 0, length);
// capture how much time was spent writing
tickdata = Util.EnvironmentTickCountSubtract(tickstart);
@@ -812,7 +837,11 @@ namespace OpenSim.Framework
try
{
using (Stream respStream = response.GetResponseStream())
+ {
+ if (WebUtil.DebugLevel >= 5)
+ WebUtil.LogResponseDetail(respStream);
deserial = (TResponse)deserializer.Deserialize(respStream);
+ }
}
catch (System.InvalidOperationException)
{
@@ -837,7 +866,11 @@ namespace OpenSim.Framework
try
{
using (Stream respStream = response.GetResponseStream())
+ {
+ if (WebUtil.DebugLevel >= 5)
+ WebUtil.LogResponseDetail(respStream);
deserial = (TResponse)deserializer.Deserialize(respStream);
+ }
}
catch (System.InvalidOperationException)
{
@@ -907,7 +940,7 @@ namespace OpenSim.Framework
}
m_log.InfoFormat(
- "[ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+ "[LOGHTTP]: [ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
reqnum,
verb,
requestUrl,
@@ -918,7 +951,7 @@ namespace OpenSim.Framework
else if (WebUtil.DebugLevel >= 4)
{
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+ "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
}
@@ -951,7 +984,7 @@ namespace OpenSim.Framework
if (WebUtil.DebugLevel >= 3)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} SynchronousRestForms {1} {2}",
+ "[LOGHTTP]: HTTP OUT {0} SynchronousRestForms {1} {2}",
reqnum, verb, requestUrl);
int tickstart = Util.EnvironmentTickCount();
@@ -978,15 +1011,16 @@ namespace OpenSim.Framework
length = (int)obj.Length;
request.ContentLength = length;
+ byte[] data = buffer.ToArray();
if (WebUtil.DebugLevel >= 5)
- WebUtil.LogOutgoingDetail(buffer);
+ WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
Stream requestStream = null;
try
{
requestStream = request.GetRequestStream();
- requestStream.Write(buffer.ToArray(), 0, length);
+ requestStream.Write(data, 0, length);
}
catch (Exception e)
{
@@ -1036,7 +1070,7 @@ namespace OpenSim.Framework
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > WebUtil.LongCallTime)
m_log.InfoFormat(
- "[FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+ "[LOGHTTP]: [FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
reqnum,
verb,
requestUrl,
@@ -1045,9 +1079,12 @@ namespace OpenSim.Framework
obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj);
else if (WebUtil.DebugLevel >= 4)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+ "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
+ if (WebUtil.DebugLevel >= 5)
+ WebUtil.LogResponseDetail(respstring);
+
return respstring;
}
@@ -1089,7 +1126,7 @@ namespace OpenSim.Framework
if (WebUtil.DebugLevel >= 3)
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} SynchronousRestObject {1} {2}",
+ "[LOGHTTP]: HTTP OUT {0} SynchronousRestObject {1} {2}",
reqnum, verb, requestUrl);
int tickstart = Util.EnvironmentTickCount();
@@ -1126,14 +1163,15 @@ namespace OpenSim.Framework
int length = (int)buffer.Length;
request.ContentLength = length;
+ byte[] data = buffer.ToArray();
if (WebUtil.DebugLevel >= 5)
- WebUtil.LogOutgoingDetail(buffer);
+ WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data));
try
{
using (Stream requestStream = request.GetRequestStream())
- requestStream.Write(buffer.ToArray(), 0, length);
+ requestStream.Write(data, 0, length);
}
catch (Exception e)
{
@@ -1159,7 +1197,21 @@ namespace OpenSim.Framework
using (Stream respStream = resp.GetResponseStream())
{
XmlSerializer deserializer = new XmlSerializer(typeof(TResponse));
- deserial = (TResponse)deserializer.Deserialize(respStream);
+
+ if (WebUtil.DebugLevel >= 5)
+ {
+ byte[] data = new byte[resp.ContentLength];
+ Util.ReadStream(respStream, data);
+
+ WebUtil.LogResponseDetail(System.Text.Encoding.UTF8.GetString(data));
+
+ using (MemoryStream temp = new MemoryStream(data))
+ deserial = (TResponse)deserializer.Deserialize(temp);
+ }
+ else
+ {
+ deserial = (TResponse)deserializer.Deserialize(respStream);
+ }
}
}
else
@@ -1210,7 +1262,7 @@ namespace OpenSim.Framework
}
m_log.InfoFormat(
- "[SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
+ "[LOGHTTP]: [SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}",
reqnum,
verb,
requestUrl,
@@ -1221,7 +1273,7 @@ namespace OpenSim.Framework
else if (WebUtil.DebugLevel >= 4)
{
m_log.DebugFormat(
- "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing",
+ "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing",
reqnum, tickdiff, tickdata);
}
}
@@ -1234,4 +1286,4 @@ namespace OpenSim.Framework
return deserial;
}
}
-}
\ No newline at end of file
+}
--
cgit v1.1