diff options
author | Oren Hurvitz | 2013-11-28 23:07:14 +0200 |
---|---|---|
committer | Oren Hurvitz | 2014-03-25 09:36:53 +0100 |
commit | f901a3820497e0d99accb6f5f60f6517e07c2c8f (patch) | |
tree | ced16f5b06d11e2ff109716c0682d27c8d3ed753 /OpenSim | |
parent | Fixed unit tests due to changes in the threadpool (diff) | |
download | opensim-SC_OLD-f901a3820497e0d99accb6f5f60f6517e07c2c8f.zip opensim-SC_OLD-f901a3820497e0d99accb6f5f60f6517e07c2c8f.tar.gz opensim-SC_OLD-f901a3820497e0d99accb6f5f60f6517e07c2c8f.tar.bz2 opensim-SC_OLD-f901a3820497e0d99accb6f5f60f6517e07c2c8f.tar.xz |
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
Diffstat (limited to '')
-rw-r--r-- | OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs | 52 | ||||
-rw-r--r-- | OpenSim/Framework/Util.cs | 40 | ||||
-rw-r--r-- | OpenSim/Framework/WebUtil.cs | 122 |
3 files changed, 165 insertions, 49 deletions
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; | |||
46 | using HttpListener=System.Net.HttpListener; | 46 | using HttpListener=System.Net.HttpListener; |
47 | using LogPrio=HttpServer.LogPrio; | 47 | using LogPrio=HttpServer.LogPrio; |
48 | using OpenSim.Framework.Monitoring; | 48 | using OpenSim.Framework.Monitoring; |
49 | using System.IO.Compression; | ||
49 | 50 | ||
50 | namespace OpenSim.Framework.Servers.HttpServer | 51 | namespace OpenSim.Framework.Servers.HttpServer |
51 | { | 52 | { |
@@ -690,6 +691,23 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
690 | 691 | ||
691 | if (buffer != null) | 692 | if (buffer != null) |
692 | { | 693 | { |
694 | if (WebUtil.DebugLevel >= 5) | ||
695 | { | ||
696 | string output = System.Text.Encoding.UTF8.GetString(buffer); | ||
697 | |||
698 | if (WebUtil.DebugLevel >= 6) | ||
699 | { | ||
700 | // Always truncate binary blobs. We don't have a ContentType, so detect them using the request name. | ||
701 | if ((requestHandler != null && requestHandler.Name == "GetMesh")) | ||
702 | { | ||
703 | if (output.Length > WebUtil.MaxRequestDiagLength) | ||
704 | output = output.Substring(0, WebUtil.MaxRequestDiagLength) + "..."; | ||
705 | } | ||
706 | } | ||
707 | |||
708 | WebUtil.LogResponseDetail(output); | ||
709 | } | ||
710 | |||
693 | if (!response.SendChunked && response.ContentLength64 <= 0) | 711 | if (!response.SendChunked && response.ContentLength64 <= 0) |
694 | response.ContentLength64 = buffer.LongLength; | 712 | response.ContentLength64 = buffer.LongLength; |
695 | 713 | ||
@@ -743,7 +761,7 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
743 | if (tickdiff > 3000 && requestHandler != null && requestHandler.Name != "GetTexture") | 761 | if (tickdiff > 3000 && requestHandler != null && requestHandler.Name != "GetTexture") |
744 | { | 762 | { |
745 | m_log.InfoFormat( | 763 | m_log.InfoFormat( |
746 | "[BASE HTTP SERVER]: Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms", | 764 | "[LOGHTTP] Slow handling of {0} {1} {2} {3} {4} from {5} took {6}ms", |
747 | RequestNumber, | 765 | RequestNumber, |
748 | requestMethod, | 766 | requestMethod, |
749 | uriString, | 767 | uriString, |
@@ -755,7 +773,7 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
755 | else if (DebugLevel >= 4) | 773 | else if (DebugLevel >= 4) |
756 | { | 774 | { |
757 | m_log.DebugFormat( | 775 | m_log.DebugFormat( |
758 | "[BASE HTTP SERVER]: HTTP IN {0} :{1} took {2}ms", | 776 | "[LOGHTTP] HTTP IN {0} :{1} took {2}ms", |
759 | RequestNumber, | 777 | RequestNumber, |
760 | Port, | 778 | Port, |
761 | tickdiff); | 779 | tickdiff); |
@@ -766,7 +784,7 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
766 | private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) | 784 | private void LogIncomingToStreamHandler(OSHttpRequest request, IRequestHandler requestHandler) |
767 | { | 785 | { |
768 | m_log.DebugFormat( | 786 | m_log.DebugFormat( |
769 | "[BASE HTTP SERVER]: HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}", | 787 | "[LOGHTTP] HTTP IN {0} :{1} stream handler {2} {3} {4} {5} from {6}", |
770 | RequestNumber, | 788 | RequestNumber, |
771 | Port, | 789 | Port, |
772 | request.HttpMethod, | 790 | request.HttpMethod, |
@@ -782,7 +800,7 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
782 | private void LogIncomingToContentTypeHandler(OSHttpRequest request) | 800 | private void LogIncomingToContentTypeHandler(OSHttpRequest request) |
783 | { | 801 | { |
784 | m_log.DebugFormat( | 802 | m_log.DebugFormat( |
785 | "[BASE HTTP SERVER]: HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}", | 803 | "[LOGHTTP] HTTP IN {0} :{1} {2} content type handler {3} {4} from {5}", |
786 | RequestNumber, | 804 | RequestNumber, |
787 | Port, | 805 | Port, |
788 | string.IsNullOrEmpty(request.ContentType) ? "not set" : request.ContentType, | 806 | string.IsNullOrEmpty(request.ContentType) ? "not set" : request.ContentType, |
@@ -797,7 +815,7 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
797 | private void LogIncomingToXmlRpcHandler(OSHttpRequest request) | 815 | private void LogIncomingToXmlRpcHandler(OSHttpRequest request) |
798 | { | 816 | { |
799 | m_log.DebugFormat( | 817 | m_log.DebugFormat( |
800 | "[BASE HTTP SERVER]: HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}", | 818 | "[LOGHTTP] HTTP IN {0} :{1} assumed generic XMLRPC request {2} {3} from {4}", |
801 | RequestNumber, | 819 | RequestNumber, |
802 | Port, | 820 | Port, |
803 | request.HttpMethod, | 821 | request.HttpMethod, |
@@ -810,26 +828,32 @@ namespace OpenSim.Framework.Servers.HttpServer | |||
810 | 828 | ||
811 | private void LogIncomingInDetail(OSHttpRequest request) | 829 | private void LogIncomingInDetail(OSHttpRequest request) |
812 | { | 830 | { |
813 | using (StreamReader reader = new StreamReader(Util.Copy(request.InputStream), Encoding.UTF8)) | 831 | if (request.ContentType == "application/octet-stream") |
832 | return; // never log these; they're just binary data | ||
833 | |||
834 | Stream inputStream = Util.Copy(request.InputStream); | ||
835 | |||
836 | if (request.ContentType == "application/x-gzip") | ||
837 | inputStream = new GZipStream(inputStream, System.IO.Compression.CompressionMode.Decompress); | ||
838 | |||
839 | using (StreamReader reader = new StreamReader(inputStream, Encoding.UTF8)) | ||
814 | { | 840 | { |
815 | string output; | 841 | string output; |
816 | 842 | ||
817 | if (DebugLevel == 5) | 843 | if (DebugLevel == 5) |
818 | { | 844 | { |
819 | const int sampleLength = 80; | 845 | char[] chars = new char[WebUtil.MaxRequestDiagLength + 1]; // +1 so we know to add "..." only if needed |
820 | char[] sampleChars = new char[sampleLength + 3]; | 846 | int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1); |
821 | reader.Read(sampleChars, 0, sampleLength); | 847 | output = new string(chars, 0, Math.Min(len, WebUtil.MaxRequestDiagLength)); |
822 | sampleChars[80] = '.'; | 848 | if (len > WebUtil.MaxRequestDiagLength) |
823 | sampleChars[81] = '.'; | 849 | output += "..."; |
824 | sampleChars[82] = '.'; | ||
825 | output = new string(sampleChars); | ||
826 | } | 850 | } |
827 | else | 851 | else |
828 | { | 852 | { |
829 | output = reader.ReadToEnd(); | 853 | output = reader.ReadToEnd(); |
830 | } | 854 | } |
831 | 855 | ||
832 | m_log.DebugFormat("[BASE HTTP SERVER]: {0}", output.Replace("\n", @"\n")); | 856 | m_log.DebugFormat("[LOGHTTP] {0}", Util.BinaryToASCII(output)); |
833 | } | 857 | } |
834 | } | 858 | } |
835 | 859 | ||
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 | |||
1510 | return result; | 1510 | return result; |
1511 | } | 1511 | } |
1512 | 1512 | ||
1513 | public static void BinaryToASCII(char[] chars) | ||
1514 | { | ||
1515 | for (int i = 0; i < chars.Length; i++) | ||
1516 | { | ||
1517 | char ch = chars[i]; | ||
1518 | if (ch < 32 || ch > 127) | ||
1519 | chars[i] = '.'; | ||
1520 | } | ||
1521 | } | ||
1522 | |||
1523 | public static string BinaryToASCII(string src) | ||
1524 | { | ||
1525 | char[] chars = src.ToCharArray(); | ||
1526 | BinaryToASCII(chars); | ||
1527 | return new String(chars); | ||
1528 | } | ||
1529 | |||
1530 | /// <summary> | ||
1531 | /// Reads a known number of bytes from a stream. | ||
1532 | /// Throws EndOfStreamException if the stream doesn't contain enough data. | ||
1533 | /// </summary> | ||
1534 | /// <param name="stream">The stream to read data from</param> | ||
1535 | /// <param name="data">The array to write bytes into. The array | ||
1536 | /// will be completely filled from the stream, so an appropriate | ||
1537 | /// size must be given.</param> | ||
1538 | public static void ReadStream(Stream stream, byte[] data) | ||
1539 | { | ||
1540 | int offset = 0; | ||
1541 | int remaining = data.Length; | ||
1542 | |||
1543 | while (remaining > 0) | ||
1544 | { | ||
1545 | int read = stream.Read(data, offset, remaining); | ||
1546 | if (read <= 0) | ||
1547 | throw new EndOfStreamException(String.Format("End of stream reached with {0} bytes left to read", remaining)); | ||
1548 | remaining -= read; | ||
1549 | offset += read; | ||
1550 | } | ||
1551 | } | ||
1552 | |||
1513 | public static Guid GetHashGuid(string data, string salt) | 1553 | public static Guid GetHashGuid(string data, string salt) |
1514 | { | 1554 | { |
1515 | byte[] hash = ComputeMD5Hash(data + salt); | 1555 | 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 | |||
89 | /// <remarks> | 89 | /// <remarks> |
90 | /// This is to truncate any really large post data, such as an asset. In theory, the first section should | 90 | /// This is to truncate any really large post data, such as an asset. In theory, the first section should |
91 | /// give us useful information about the call (which agent it relates to if applicable, etc.). | 91 | /// give us useful information about the call (which agent it relates to if applicable, etc.). |
92 | /// This is also used to truncate messages when using DebugLevel 5. | ||
92 | /// </remarks> | 93 | /// </remarks> |
93 | public const int MaxRequestDiagLength = 100; | 94 | public const int MaxRequestDiagLength = 200; |
94 | 95 | ||
95 | /// <summary> | 96 | /// <summary> |
96 | /// Dictionary of end points | 97 | /// Dictionary of end points |
@@ -165,35 +166,54 @@ namespace OpenSim.Framework | |||
165 | 166 | ||
166 | public static void LogOutgoingDetail(Stream outputStream) | 167 | public static void LogOutgoingDetail(Stream outputStream) |
167 | { | 168 | { |
169 | LogOutgoingDetail("", outputStream); | ||
170 | } | ||
171 | |||
172 | public static void LogOutgoingDetail(string context, Stream outputStream) | ||
173 | { | ||
168 | using (StreamReader reader = new StreamReader(Util.Copy(outputStream), Encoding.UTF8)) | 174 | using (StreamReader reader = new StreamReader(Util.Copy(outputStream), Encoding.UTF8)) |
169 | { | 175 | { |
170 | string output; | 176 | string output; |
171 | 177 | ||
172 | if (DebugLevel == 5) | 178 | if (DebugLevel == 5) |
173 | { | 179 | { |
174 | const int sampleLength = 80; | 180 | char[] chars = new char[WebUtil.MaxRequestDiagLength + 1]; // +1 so we know to add "..." only if needed |
175 | char[] sampleChars = new char[sampleLength]; | 181 | int len = reader.Read(chars, 0, WebUtil.MaxRequestDiagLength + 1); |
176 | reader.Read(sampleChars, 0, sampleLength); | 182 | output = new string(chars, 0, len); |
177 | output = new string(sampleChars); | ||
178 | } | 183 | } |
179 | else | 184 | else |
180 | { | 185 | { |
181 | output = reader.ReadToEnd(); | 186 | output = reader.ReadToEnd(); |
182 | } | 187 | } |
183 | 188 | ||
184 | LogOutgoingDetail(output); | 189 | LogOutgoingDetail(context, output); |
185 | } | 190 | } |
186 | } | 191 | } |
187 | 192 | ||
188 | public static void LogOutgoingDetail(string output) | 193 | public static void LogOutgoingDetail(string output) |
189 | { | 194 | { |
195 | LogOutgoingDetail("", output); | ||
196 | } | ||
197 | |||
198 | public static void LogOutgoingDetail(string context, string output) | ||
199 | { | ||
190 | if (DebugLevel == 5) | 200 | if (DebugLevel == 5) |
191 | { | 201 | { |
192 | output = output.Substring(0, 80); | 202 | if (output.Length > MaxRequestDiagLength) |
193 | output = output + "..."; | 203 | output = output.Substring(0, MaxRequestDiagLength) + "..."; |
194 | } | 204 | } |
195 | 205 | ||
196 | m_log.DebugFormat("[WEB UTIL]: {0}", output.Replace("\n", @"\n")); | 206 | m_log.DebugFormat("[LOGHTTP]: {0}{1}", context, Util.BinaryToASCII(output)); |
207 | } | ||
208 | |||
209 | public static void LogResponseDetail(Stream inputStream) | ||
210 | { | ||
211 | LogOutgoingDetail("RESPONSE: ", inputStream); | ||
212 | } | ||
213 | |||
214 | public static void LogResponseDetail(string input) | ||
215 | { | ||
216 | LogOutgoingDetail("RESPONSE: ", input); | ||
197 | } | 217 | } |
198 | 218 | ||
199 | private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed) | 219 | private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed) |
@@ -202,7 +222,7 @@ namespace OpenSim.Framework | |||
202 | 222 | ||
203 | if (DebugLevel >= 3) | 223 | if (DebugLevel >= 3) |
204 | m_log.DebugFormat( | 224 | m_log.DebugFormat( |
205 | "[WEB UTIL]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})", | 225 | "[LOGHTTP]: HTTP OUT {0} ServiceOSD {1} {2} (timeout {3}, compressed {4})", |
206 | reqnum, method, url, timeout, compressed); | 226 | reqnum, method, url, timeout, compressed); |
207 | 227 | ||
208 | string errorMessage = "unknown error"; | 228 | string errorMessage = "unknown error"; |
@@ -268,7 +288,9 @@ namespace OpenSim.Framework | |||
268 | using (StreamReader reader = new StreamReader(responseStream)) | 288 | using (StreamReader reader = new StreamReader(responseStream)) |
269 | { | 289 | { |
270 | string responseStr = reader.ReadToEnd(); | 290 | string responseStr = reader.ReadToEnd(); |
271 | // m_log.DebugFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr); | 291 | // m_log.DebugFormat("[LOGHTTP]: <{0}> response is <{1}>",reqnum,responseStr); |
292 | if (WebUtil.DebugLevel >= 5) | ||
293 | WebUtil.LogResponseDetail(responseStr); | ||
272 | return CanonicalizeResults(responseStr); | 294 | return CanonicalizeResults(responseStr); |
273 | } | 295 | } |
274 | } | 296 | } |
@@ -292,7 +314,7 @@ namespace OpenSim.Framework | |||
292 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); | 314 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); |
293 | if (tickdiff > LongCallTime) | 315 | if (tickdiff > LongCallTime) |
294 | m_log.InfoFormat( | 316 | m_log.InfoFormat( |
295 | "[WEB UTIL]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}", | 317 | "[LOGHTTP]: Slow ServiceOSD request {0} {1} {2} took {3}ms, {4}ms writing, {5}", |
296 | reqnum, | 318 | reqnum, |
297 | method, | 319 | method, |
298 | url, | 320 | url, |
@@ -303,12 +325,12 @@ namespace OpenSim.Framework | |||
303 | : ""); | 325 | : ""); |
304 | else if (DebugLevel >= 4) | 326 | else if (DebugLevel >= 4) |
305 | m_log.DebugFormat( | 327 | m_log.DebugFormat( |
306 | "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", | 328 | "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", |
307 | reqnum, tickdiff, tickdata); | 329 | reqnum, tickdiff, tickdata); |
308 | } | 330 | } |
309 | 331 | ||
310 | m_log.DebugFormat( | 332 | m_log.DebugFormat( |
311 | "[WEB UTIL]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage); | 333 | "[LOGHTTP]: ServiceOSD request {0} {1} {2} FAILED: {3}", reqnum, url, method, errorMessage); |
312 | 334 | ||
313 | return ErrorResponseMap(errorMessage); | 335 | return ErrorResponseMap(errorMessage); |
314 | } | 336 | } |
@@ -387,7 +409,7 @@ namespace OpenSim.Framework | |||
387 | 409 | ||
388 | if (DebugLevel >= 3) | 410 | if (DebugLevel >= 3) |
389 | m_log.DebugFormat( | 411 | m_log.DebugFormat( |
390 | "[WEB UTIL]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})", | 412 | "[LOGHTTP]: HTTP OUT {0} ServiceForm {1} {2} (timeout {3})", |
391 | reqnum, method, url, timeout); | 413 | reqnum, method, url, timeout); |
392 | 414 | ||
393 | string errorMessage = "unknown error"; | 415 | string errorMessage = "unknown error"; |
@@ -431,6 +453,8 @@ namespace OpenSim.Framework | |||
431 | using (StreamReader reader = new StreamReader(responseStream)) | 453 | using (StreamReader reader = new StreamReader(responseStream)) |
432 | { | 454 | { |
433 | string responseStr = reader.ReadToEnd(); | 455 | string responseStr = reader.ReadToEnd(); |
456 | if (WebUtil.DebugLevel >= 5) | ||
457 | WebUtil.LogResponseDetail(responseStr); | ||
434 | OSD responseOSD = OSDParser.Deserialize(responseStr); | 458 | OSD responseOSD = OSDParser.Deserialize(responseStr); |
435 | 459 | ||
436 | if (responseOSD.Type == OSDType.Map) | 460 | if (responseOSD.Type == OSDType.Map) |
@@ -457,7 +481,7 @@ namespace OpenSim.Framework | |||
457 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); | 481 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); |
458 | if (tickdiff > LongCallTime) | 482 | if (tickdiff > LongCallTime) |
459 | m_log.InfoFormat( | 483 | m_log.InfoFormat( |
460 | "[WEB UTIL]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}", | 484 | "[LOGHTTP]: Slow ServiceForm request {0} {1} {2} took {3}ms, {4}ms writing, {5}", |
461 | reqnum, | 485 | reqnum, |
462 | method, | 486 | method, |
463 | url, | 487 | url, |
@@ -468,11 +492,11 @@ namespace OpenSim.Framework | |||
468 | : ""); | 492 | : ""); |
469 | else if (DebugLevel >= 4) | 493 | else if (DebugLevel >= 4) |
470 | m_log.DebugFormat( | 494 | m_log.DebugFormat( |
471 | "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", | 495 | "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", |
472 | reqnum, tickdiff, tickdata); | 496 | reqnum, tickdiff, tickdata); |
473 | } | 497 | } |
474 | 498 | ||
475 | m_log.WarnFormat("[WEB UTIL]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage); | 499 | m_log.WarnFormat("[LOGHTTP]: ServiceForm request {0} {1} {2} failed: {2}", reqnum, method, url, errorMessage); |
476 | 500 | ||
477 | return ErrorResponseMap(errorMessage); | 501 | return ErrorResponseMap(errorMessage); |
478 | } | 502 | } |
@@ -753,7 +777,7 @@ namespace OpenSim.Framework | |||
753 | 777 | ||
754 | if (WebUtil.DebugLevel >= 3) | 778 | if (WebUtil.DebugLevel >= 3) |
755 | m_log.DebugFormat( | 779 | m_log.DebugFormat( |
756 | "[WEB UTIL]: HTTP OUT {0} AsynchronousRequestObject {1} {2}", | 780 | "[LOGHTTP]: HTTP OUT {0} AsynchronousRequestObject {1} {2}", |
757 | reqnum, verb, requestUrl); | 781 | reqnum, verb, requestUrl); |
758 | 782 | ||
759 | int tickstart = Util.EnvironmentTickCount(); | 783 | int tickstart = Util.EnvironmentTickCount(); |
@@ -793,14 +817,15 @@ namespace OpenSim.Framework | |||
793 | 817 | ||
794 | int length = (int)buffer.Length; | 818 | int length = (int)buffer.Length; |
795 | request.ContentLength = length; | 819 | request.ContentLength = length; |
820 | byte[] data = buffer.ToArray(); | ||
796 | 821 | ||
797 | if (WebUtil.DebugLevel >= 5) | 822 | if (WebUtil.DebugLevel >= 5) |
798 | WebUtil.LogOutgoingDetail(buffer); | 823 | WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); |
799 | 824 | ||
800 | request.BeginGetRequestStream(delegate(IAsyncResult res) | 825 | request.BeginGetRequestStream(delegate(IAsyncResult res) |
801 | { | 826 | { |
802 | using (Stream requestStream = request.EndGetRequestStream(res)) | 827 | using (Stream requestStream = request.EndGetRequestStream(res)) |
803 | requestStream.Write(buffer.ToArray(), 0, length); | 828 | requestStream.Write(data, 0, length); |
804 | 829 | ||
805 | // capture how much time was spent writing | 830 | // capture how much time was spent writing |
806 | tickdata = Util.EnvironmentTickCountSubtract(tickstart); | 831 | tickdata = Util.EnvironmentTickCountSubtract(tickstart); |
@@ -812,7 +837,11 @@ namespace OpenSim.Framework | |||
812 | try | 837 | try |
813 | { | 838 | { |
814 | using (Stream respStream = response.GetResponseStream()) | 839 | using (Stream respStream = response.GetResponseStream()) |
840 | { | ||
841 | if (WebUtil.DebugLevel >= 5) | ||
842 | WebUtil.LogResponseDetail(respStream); | ||
815 | deserial = (TResponse)deserializer.Deserialize(respStream); | 843 | deserial = (TResponse)deserializer.Deserialize(respStream); |
844 | } | ||
816 | } | 845 | } |
817 | catch (System.InvalidOperationException) | 846 | catch (System.InvalidOperationException) |
818 | { | 847 | { |
@@ -837,7 +866,11 @@ namespace OpenSim.Framework | |||
837 | try | 866 | try |
838 | { | 867 | { |
839 | using (Stream respStream = response.GetResponseStream()) | 868 | using (Stream respStream = response.GetResponseStream()) |
869 | { | ||
870 | if (WebUtil.DebugLevel >= 5) | ||
871 | WebUtil.LogResponseDetail(respStream); | ||
840 | deserial = (TResponse)deserializer.Deserialize(respStream); | 872 | deserial = (TResponse)deserializer.Deserialize(respStream); |
873 | } | ||
841 | } | 874 | } |
842 | catch (System.InvalidOperationException) | 875 | catch (System.InvalidOperationException) |
843 | { | 876 | { |
@@ -907,7 +940,7 @@ namespace OpenSim.Framework | |||
907 | } | 940 | } |
908 | 941 | ||
909 | m_log.InfoFormat( | 942 | m_log.InfoFormat( |
910 | "[ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", | 943 | "[LOGHTTP]: [ASYNC REQUEST]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", |
911 | reqnum, | 944 | reqnum, |
912 | verb, | 945 | verb, |
913 | requestUrl, | 946 | requestUrl, |
@@ -918,7 +951,7 @@ namespace OpenSim.Framework | |||
918 | else if (WebUtil.DebugLevel >= 4) | 951 | else if (WebUtil.DebugLevel >= 4) |
919 | { | 952 | { |
920 | m_log.DebugFormat( | 953 | m_log.DebugFormat( |
921 | "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", | 954 | "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", |
922 | reqnum, tickdiff, tickdata); | 955 | reqnum, tickdiff, tickdata); |
923 | } | 956 | } |
924 | } | 957 | } |
@@ -951,7 +984,7 @@ namespace OpenSim.Framework | |||
951 | 984 | ||
952 | if (WebUtil.DebugLevel >= 3) | 985 | if (WebUtil.DebugLevel >= 3) |
953 | m_log.DebugFormat( | 986 | m_log.DebugFormat( |
954 | "[WEB UTIL]: HTTP OUT {0} SynchronousRestForms {1} {2}", | 987 | "[LOGHTTP]: HTTP OUT {0} SynchronousRestForms {1} {2}", |
955 | reqnum, verb, requestUrl); | 988 | reqnum, verb, requestUrl); |
956 | 989 | ||
957 | int tickstart = Util.EnvironmentTickCount(); | 990 | int tickstart = Util.EnvironmentTickCount(); |
@@ -978,15 +1011,16 @@ namespace OpenSim.Framework | |||
978 | 1011 | ||
979 | length = (int)obj.Length; | 1012 | length = (int)obj.Length; |
980 | request.ContentLength = length; | 1013 | request.ContentLength = length; |
1014 | byte[] data = buffer.ToArray(); | ||
981 | 1015 | ||
982 | if (WebUtil.DebugLevel >= 5) | 1016 | if (WebUtil.DebugLevel >= 5) |
983 | WebUtil.LogOutgoingDetail(buffer); | 1017 | WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); |
984 | 1018 | ||
985 | Stream requestStream = null; | 1019 | Stream requestStream = null; |
986 | try | 1020 | try |
987 | { | 1021 | { |
988 | requestStream = request.GetRequestStream(); | 1022 | requestStream = request.GetRequestStream(); |
989 | requestStream.Write(buffer.ToArray(), 0, length); | 1023 | requestStream.Write(data, 0, length); |
990 | } | 1024 | } |
991 | catch (Exception e) | 1025 | catch (Exception e) |
992 | { | 1026 | { |
@@ -1036,7 +1070,7 @@ namespace OpenSim.Framework | |||
1036 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); | 1070 | int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); |
1037 | if (tickdiff > WebUtil.LongCallTime) | 1071 | if (tickdiff > WebUtil.LongCallTime) |
1038 | m_log.InfoFormat( | 1072 | m_log.InfoFormat( |
1039 | "[FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", | 1073 | "[LOGHTTP]: [FORMS]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", |
1040 | reqnum, | 1074 | reqnum, |
1041 | verb, | 1075 | verb, |
1042 | requestUrl, | 1076 | requestUrl, |
@@ -1045,9 +1079,12 @@ namespace OpenSim.Framework | |||
1045 | obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj); | 1079 | obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj); |
1046 | else if (WebUtil.DebugLevel >= 4) | 1080 | else if (WebUtil.DebugLevel >= 4) |
1047 | m_log.DebugFormat( | 1081 | m_log.DebugFormat( |
1048 | "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", | 1082 | "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", |
1049 | reqnum, tickdiff, tickdata); | 1083 | reqnum, tickdiff, tickdata); |
1050 | 1084 | ||
1085 | if (WebUtil.DebugLevel >= 5) | ||
1086 | WebUtil.LogResponseDetail(respstring); | ||
1087 | |||
1051 | return respstring; | 1088 | return respstring; |
1052 | } | 1089 | } |
1053 | 1090 | ||
@@ -1089,7 +1126,7 @@ namespace OpenSim.Framework | |||
1089 | 1126 | ||
1090 | if (WebUtil.DebugLevel >= 3) | 1127 | if (WebUtil.DebugLevel >= 3) |
1091 | m_log.DebugFormat( | 1128 | m_log.DebugFormat( |
1092 | "[WEB UTIL]: HTTP OUT {0} SynchronousRestObject {1} {2}", | 1129 | "[LOGHTTP]: HTTP OUT {0} SynchronousRestObject {1} {2}", |
1093 | reqnum, verb, requestUrl); | 1130 | reqnum, verb, requestUrl); |
1094 | 1131 | ||
1095 | int tickstart = Util.EnvironmentTickCount(); | 1132 | int tickstart = Util.EnvironmentTickCount(); |
@@ -1126,14 +1163,15 @@ namespace OpenSim.Framework | |||
1126 | 1163 | ||
1127 | int length = (int)buffer.Length; | 1164 | int length = (int)buffer.Length; |
1128 | request.ContentLength = length; | 1165 | request.ContentLength = length; |
1166 | byte[] data = buffer.ToArray(); | ||
1129 | 1167 | ||
1130 | if (WebUtil.DebugLevel >= 5) | 1168 | if (WebUtil.DebugLevel >= 5) |
1131 | WebUtil.LogOutgoingDetail(buffer); | 1169 | WebUtil.LogOutgoingDetail(System.Text.Encoding.UTF8.GetString(data)); |
1132 | 1170 | ||
1133 | try | 1171 | try |
1134 | { | 1172 | { |
1135 | using (Stream requestStream = request.GetRequestStream()) | 1173 | using (Stream requestStream = request.GetRequestStream()) |
1136 | requestStream.Write(buffer.ToArray(), 0, length); | 1174 | requestStream.Write(data, 0, length); |
1137 | } | 1175 | } |
1138 | catch (Exception e) | 1176 | catch (Exception e) |
1139 | { | 1177 | { |
@@ -1159,7 +1197,21 @@ namespace OpenSim.Framework | |||
1159 | using (Stream respStream = resp.GetResponseStream()) | 1197 | using (Stream respStream = resp.GetResponseStream()) |
1160 | { | 1198 | { |
1161 | XmlSerializer deserializer = new XmlSerializer(typeof(TResponse)); | 1199 | XmlSerializer deserializer = new XmlSerializer(typeof(TResponse)); |
1162 | deserial = (TResponse)deserializer.Deserialize(respStream); | 1200 | |
1201 | if (WebUtil.DebugLevel >= 5) | ||
1202 | { | ||
1203 | byte[] data = new byte[resp.ContentLength]; | ||
1204 | Util.ReadStream(respStream, data); | ||
1205 | |||
1206 | WebUtil.LogResponseDetail(System.Text.Encoding.UTF8.GetString(data)); | ||
1207 | |||
1208 | using (MemoryStream temp = new MemoryStream(data)) | ||
1209 | deserial = (TResponse)deserializer.Deserialize(temp); | ||
1210 | } | ||
1211 | else | ||
1212 | { | ||
1213 | deserial = (TResponse)deserializer.Deserialize(respStream); | ||
1214 | } | ||
1163 | } | 1215 | } |
1164 | } | 1216 | } |
1165 | else | 1217 | else |
@@ -1210,7 +1262,7 @@ namespace OpenSim.Framework | |||
1210 | } | 1262 | } |
1211 | 1263 | ||
1212 | m_log.InfoFormat( | 1264 | m_log.InfoFormat( |
1213 | "[SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", | 1265 | "[LOGHTTP]: [SynchronousRestObjectRequester]: Slow request {0} {1} {2} took {3}ms, {4}ms writing, {5}", |
1214 | reqnum, | 1266 | reqnum, |
1215 | verb, | 1267 | verb, |
1216 | requestUrl, | 1268 | requestUrl, |
@@ -1221,7 +1273,7 @@ namespace OpenSim.Framework | |||
1221 | else if (WebUtil.DebugLevel >= 4) | 1273 | else if (WebUtil.DebugLevel >= 4) |
1222 | { | 1274 | { |
1223 | m_log.DebugFormat( | 1275 | m_log.DebugFormat( |
1224 | "[WEB UTIL]: HTTP OUT {0} took {1}ms, {2}ms writing", | 1276 | "[LOGHTTP]: HTTP OUT {0} took {1}ms, {2}ms writing", |
1225 | reqnum, tickdiff, tickdata); | 1277 | reqnum, tickdiff, tickdata); |
1226 | } | 1278 | } |
1227 | } | 1279 | } |
@@ -1234,4 +1286,4 @@ namespace OpenSim.Framework | |||
1234 | return deserial; | 1286 | return deserial; |
1235 | } | 1287 | } |
1236 | } | 1288 | } |
1237 | } \ No newline at end of file | 1289 | } |