In one of our applications I recently observed timeouts in code performing HTTP requests to the REST service. While investigating this issue I discovered few interesting facts about System.Net namespace and would like to share them with you. We were using objects of type System.Net.HttpWebRequest in our code, but some of the information presented in this post will also apply to the newer System.Net.HttpClient implementation.
Exception analysis
Firstly, we will reproduce the issue with a sample application measuring WG.NET (Warsaw .NET group website) response time:
using System; using System.Diagnostics; using System.Net; public class Program { public static void Main(String[] args) { var sw = new Stopwatch(); var logger = new TraceSource("LowLevelDesign"); while (true) { logger.TraceEvent(TraceEventType.Information, 0, "HTTP request to wg.net.pl"); sw.Restart(); try { var request = WebRequest.Create("http://www.wg.net.pl"); request.GetResponse(); } catch (Exception ex) { logger.TraceEvent(TraceEventType.Information, 0, "Exception: {0}", ex); } logger.TraceEvent(TraceEventType.Information, 0, "The request took: {0} ms", sw.ElapsedMilliseconds); } } }
Compile and run it:
LowLevelDesign Information: 0 : HTTP request to wg.net.pl DateTime=2015-03-07T11:50:11.5547493Z LowLevelDesign Information: 0 : The request took: 746 ms DateTime=2015-03-07T11:50:12.3026958Z LowLevelDesign Information: 0 : HTTP request to wg.net.pl DateTime=2015-03-07T11:50:12.3116971Z LowLevelDesign Information: 0 : The request took: 573 ms DateTime=2015-03-07T11:50:12.8889227Z LowLevelDesign Information: 0 : HTTP request to wg.net.pl DateTime=2015-03-07T11:50:12.8949109Z LowLevelDesign Information: 0 : Exception: System.Net.WebException: The operation has timed out at System.Net.HttpWebRequest.GetResponse() at Program.Main(String[] args) in c:\Users\admin\code\TestRequest.cs:line 17 DateTime=2015-03-07T11:51:52.9159422Z LowLevelDesign Information: 0 : The request took: 100019 ms
Did you notice an exception in the output? Now, look back at the source code and guess what is wrong. Don’t worry if you don’t know – few days ago I didn’t know either 🙂 So I turned on additional log sources from System.Net classes in the application configuration file (you can find more information about them in my Network tracing in .NET debug recipe):
<?xml version="1.0" ?> <configuration> <system.diagnostics> <trace autoflush="true"> </trace> <sharedListeners> <add name="console" type="System.Diagnostics.ConsoleTraceListener" traceOutputOptions="DateTime" /> <add name="file" type="System.Diagnostics.TextWriterTraceListener" initializeData="d:\logs\testrequest.log" traceOutputOptions="DateTime, Callstack" /> </sharedListeners> <sources> <source name="LowLevelDesign" switchValue="Verbose"> <listeners> <add name="file" /> <add name="console" /> </listeners> </source> <source name="System.Net.Http" switchValue="Verbose"> <listeners> <add name="file" /> </listeners> </source> <source name="System.Net.HttpListener" switchValue="Verbose"> <listeners> <add name="file" /> </listeners> </source> <source name="System.Net" switchValue="Verbose"> <listeners> <add name="file" /> </listeners> </source> <source name="System.Net.Sockets" switchValue="Verbose"> <listeners> <add name="file" /> </listeners> </source> </sources> </system.diagnostics> </configuration>
The generated log will contain detailed information about System.Net classes internal work. We need to find a reason why the timeout exception happened. If we look into the log file the normal request consists of the following operations (call stacks and datetimes are stripped):
LowLevelDesign Information: 0 : HTTP request to wg.net.pl System.Net Verbose: 0 : [2764] WebRequest::Create(http://www.wg.net.pl/) System.Net Verbose: 0 : [2764] HttpWebRequest#60068066::HttpWebRequest(http://www.wg.net.pl/#1977127123) System.Net Information: 0 : [2764] Current OS installation type is 'Client'. System.Net Information: 0 : [2764] RAS supported: True System.Net Verbose: 0 : [2764] Exiting HttpWebRequest#60068066::HttpWebRequest() System.Net Verbose: 0 : [2764] Exiting WebRequest::Create() -> HttpWebRequest#60068066 System.Net Verbose: 0 : [2764] HttpWebRequest#60068066::GetResponse() System.Net Error: 0 : [2764] Can't retrieve proxy settings for Uri 'http://www.wg.net.pl/'. Error code: 12180. System.Net Verbose: 0 : [2764] ServicePoint#34640832::ServicePoint(www.wg.net.pl:80) System.Net Information: 0 : [2764] Associating HttpWebRequest#60068066 with ServicePoint#34640832 System.Net Information: 0 : [2764] Associating Connection#43332040 with HttpWebRequest#60068066 System.Net.Sockets Verbose: 0 : [2764] Socket#54444047::Socket(AddressFamily#2) System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#54444047::Socket() System.Net.Sockets Verbose: 0 : [2764] Socket#20234383::Socket(AddressFamily#23) System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#20234383::Socket() System.Net.Sockets Verbose: 0 : [2764] DNS::TryInternalResolve(www.wg.net.pl) System.Net.Sockets Verbose: 0 : [2764] Socket#54444047::Connect(64.233.162.121:80#2040719632) System.Net.Sockets Information: 0 : [2764] Socket#54444047 - Created connection from 192.168.1.14:59576 to 64.233.162.121:80. System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#54444047::Connect() System.Net.Sockets Verbose: 0 : [2764] Socket#20234383::Close() System.Net.Sockets Verbose: 0 : [2764] Socket#20234383::Dispose() System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#20234383::Close() System.Net Information: 0 : [2764] Connection#43332040 - Created connection from 192.168.1.14:59576 to 64.233.162.121:80. System.Net Information: 0 : [2764] Associating HttpWebRequest#60068066 with ConnectStream#47891719 System.Net Information: 0 : [2764] HttpWebRequest#60068066 - Request: GET / HTTP/1.1 System.Net Information: 0 : [2764] ConnectStream#47891719 - Sending headers { Host: www.wg.net.pl Connection: Keep-Alive }. System.Net.Sockets Verbose: 0 : [2764] Socket#54444047::Send() System.Net.Sockets Verbose: 0 : [2764] Data from Socket#54444047::Send System.Net.Sockets Verbose: 0 : [2764] 00000000 : 47 45 54 20 2F 20 48 54-54 50 2F 31 2E 31 0D 0A : GET / HTTP/1.1.. System.Net.Sockets Verbose: 0 : [2764] 00000010 : 48 6F 73 74 3A 20 77 77-77 2E 77 67 2E 6E 65 74 : Host: www.wg.net System.Net.Sockets Verbose: 0 : [2764] 00000020 : 2E 70 6C 0D 0A 43 6F 6E-6E 65 63 74 69 6F 6E 3A : .pl..Connection: System.Net.Sockets Verbose: 0 : [2764] 00000030 : 20 4B 65 65 70 2D 41 6C-69 76 65 0D 0A 0D 0A : Keep-Alive.... System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#54444047::Send() -> Int32#63 System.Net.Sockets Verbose: 0 : [2764] Socket#54444047::Receive() System.Net.Sockets Verbose: 0 : [2764] Data from Socket#54444047::Receive System.Net.Sockets Verbose: 0 : [2764] (printing 1024 out of 4096) System.Net.Sockets Verbose: 0 : [2764] 00000000 : 48 54 54 50 2F 31 2E 31-20 32 30 30 20 4F 4B 0D : HTTP/1.1 200 OK. ... System.Net.Sockets Verbose: 0 : [2764] 000003F0 : 5B 76 6F 69 64 20 30 21-3D 63 3F 63 3A 28 6E 65 : [void 0!=c?c:(ne System.Net.Sockets Verbose: 0 : [2764] Exiting Socket#54444047::Receive() -> Int32#4096 System.Net Information: 0 : [2764] Connection#43332040 - Received status line: Version=1.1, StatusCode=200, StatusDescription=OK. System.Net Information: 0 : [2764] Connection#43332040 - Received headers { X-Frame-Options: SAMEORIGIN X-Robots-Tag: noarchive X-Content-Type-Options: nosniff X-XSS-Protection: 1; mode=block Alternate-Protocol: 80:quic,p=0.08,80:quic,p=0.08 Vary: Accept-Encoding Transfer-Encoding: chunked Accept-Ranges: none Cache-Control: public, max-age=5 Content-Type: text/html; charset=utf-8 Date: Sat, 07 Mar 2015 11:50:12 GMT Expires: Sat, 07 Mar 2015 11:50:17 GMT Last-Modified: Fri, 06 Mar 2015 12:02:01 GMT Server: GSE }. System.Net Information: 0 : [2764] ConnectStream#28372289::ConnectStream(Buffered -1 bytes.) System.Net Information: 0 : [2764] Associating HttpWebRequest#60068066 with ConnectStream#28372289 System.Net Information: 0 : [2764] Associating HttpWebRequest#60068066 with HttpWebResponse#54024015 System.Net Verbose: 0 : [2764] Exiting HttpWebRequest#60068066::GetResponse() -> HttpWebResponse#54024015 LowLevelDesign Information: 0 : The request took: 746 ms
and the timed out request:
LowLevelDesign Information: 0 : HTTP request to wg.net.pl System.Net Verbose: 0 : [2764] WebRequest::Create(http://www.wg.net.pl/) System.Net Verbose: 0 : [2764] HttpWebRequest#26753075::HttpWebRequest(http://www.wg.net.pl/#1977127123) System.Net Verbose: 0 : [2764] Exiting HttpWebRequest#26753075::HttpWebRequest() System.Net Verbose: 0 : [2764] Exiting WebRequest::Create() -> HttpWebRequest#26753075 System.Net Verbose: 0 : [2764] HttpWebRequest#26753075::GetResponse() System.Net Information: 0 : [2764] Associating HttpWebRequest#26753075 with ServicePoint#34640832 System.Net Information: 0 : [2764] Associating Connection#43332040 with HttpWebRequest#26753075 System.Net Verbose: 0 : [6776] HttpWebRequest#26753075::Abort(The operation has timed out) System.Net Error: 0 : [6776] Exception in HttpWebRequest#26753075:: - The operation has timed out. System.Net Verbose: 0 : [6776] Exiting HttpWebRequest#26753075::Abort() System.Net Error: 0 : [2764] Exception in HttpWebRequest#26753075::GetResponse - The operation has timed out. LowLevelDesign Information: 0 : Exception: System.Net.WebException: The operation has timed out at System.Net.HttpWebRequest.GetResponse() at Program.Main(String[] args) in c:\Users\Sebastian\Dysk Google\lab\webrequest-timeout\code\TestRequest.cs:line 17 LowLevelDesign Information: 0 : The request took: 100019 ms
If we turn on call stacks in the trace log (traceOutputOptions) we would see that the last operation before the exception occurred was System.Net.Connection.SubmitRequest
:
System.Net Information: 0 : [5616] Associating Connection#13869071 with HttpWebRequest#58328727 DateTime=2015-03-07T11:30:12.0283827Z Callstack= at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) at System.Environment.get_StackTrace() at System.Diagnostics.TraceEventCache.get_Callstack() at System.Diagnostics.TraceListener.WriteFooter(TraceEventCache eventCache) at System.Diagnostics.TraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String message) at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message) at System.Net.Logging.PrintLine(TraceSource traceSource, TraceEventType eventType, Int32 id, String msg) at System.Net.Logging.Associate(TraceSource traceSource, Object objA, Object objB) at System.Net.Connection.SubmitRequest(HttpWebRequest request, Boolean forcedsubmit) at System.Net.ServicePoint.SubmitRequest(HttpWebRequest request, String connName) at System.Net.HttpWebRequest.SubmitRequest(ServicePoint servicePoint) at System.Net.HttpWebRequest.GetResponse()
Checking .NET source code we could see that the possible place where this method might hang is:
if (!request.Async) { object responseObject = request.ConnectionAsyncResult.InternalWaitForCompletion(); ConnectStream writeStream = responseObject as ConnectStream; ...
There comes a moment when we need to take a step back and understand how System.Net requests are performed.
System.Net nuances and configuration settings
Each time you create a request, there is a System.Net.ServicePoint assigned to it. ServicePoint then tries to find a connection which will serve a given request. Each write and read operation on a connection is performed by a ConnectStream instance. Connections are pooled and their number is by default limited to two connections per IP address. You may configure the maximum number of connections per IP address or DNS name in the application configuration file (section system.net\connectionManagement\add), eg.:
<configuration> <system.net> <connectionManagement> <add address = "http://www.wg.net.pl" maxconnection = "4" /> <add address = "*" maxconnection = "2" /> </connectionManagement> </system.net> </configuration>
This explains why we received a timeout after two successful requests. We might now suspect that our first requests are blocking subsequent ones, but why? Let’s collect a memory dump while the application is waiting for a request to finish (you may find information how to collect a memory dump in this recipe).
Analysing a memory dump
We open the dump in WinDbg. Then we load the SOS extension with a command: .loadby sos clr
and display the current thread’s stack with !CLRStack -a
:
OS Thread Id: 0xa18 (0) Child SP IP Call Site 00eaec60 7709cc2c [HelperMethodFrame_1OBJ: 00eaec60] System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean) 00eaed44 728b64f0 System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean) PARAMETERS: waitableSafeHandle = millisecondsTimeout = hasThreadAffinity = exitContext = LOCALS: 00eaed5c 728b64c4 System.Threading.WaitHandle.WaitOne(Int32, Boolean) PARAMETERS: this = millisecondsTimeout = exitContext = 00eaed70 71cea6b1 System.Net.LazyAsyncResult.WaitForCompletion(Boolean) PARAMETERS: this (0x00eaed70) = 0x02d9ca5c snap = LOCALS: 0x00eaed74 = 0x00000001 00eaeda0 71cfe3cf System.Net.Connection.SubmitRequest(System.Net.HttpWebRequest, Boolean) PARAMETERS: this (0x00eaeda8) = 0x02c9c204 request (0x00eaeda4) = 0x02d84a28 forcedsubmit = LOCALS: 0x00eaedbc = 0xffffffff 0x00eaedb8 = 0x00000000 0x00eaedb0 = 0x00000001 00eaede8 71cfcf3b System.Net.ServicePoint.SubmitRequest(System.Net.HttpWebRequest, System.String) PARAMETERS: this = ...
Let’s then find which objects reference the connection assigned to our request (0x02c9c204):
0:000> !GCRoot -all 0x02c9c204 Thread a18: 00eaed70 71cea6b1 System.Net.LazyAsyncResult.WaitForCompletion(Boolean) ebp+28: 00eaed70 -> 02d9ca5c System.Net.LazyAsyncResult -> 02d84a28 System.Net.HttpWebRequest -> 02c9b0e4 System.Net.ServicePoint -> 02c9b1ac System.Collections.Hashtable -> 02c9b1e0 System.Collections.Hashtable+bucket[] -> 02c9c110 System.Net.ConnectionGroup -> 02c9c1b0 System.Collections.ArrayList -> 02c9c1c8 System.Object[] -> 02c9c204 System.Net.Connection 00eaeda0 71cfe3cf System.Net.Connection.SubmitRequest(System.Net.HttpWebRequest, Boolean) ebp+34: 00eaeda8 -> 02c9c204 System.Net.Connection ... 00eaee90 010b0126 Program.Main(System.String[]) [c:\Users\Sebastian\Dysk Google\lab\webrequest-timeout\TestRequest.cs @ 17] ebp+64: 00eaeeb4 -> 02d69fbc System.Net.HttpWebResponse -> 02d5fe2c System.Net.ConnectStream -> 02cadf4c System.Net.Connection -> 02c9c110 System.Net.ConnectionGroup -> 02c9c1b0 System.Collections.ArrayList -> 02c9c1c8 System.Object[] -> 02c9c204 System.Net.Connection ... Found 13 roots.
References coming from the ServicePoint are expected as we have a request waiting on this connection. What we do not expect is a reference from a ConnectStream coming from some HttpWebResponse instance. Let’s dump the ConnectStream instance:
0:000> !do 02d5fe2c Name: System.Net.ConnectStream MethodTable: 71d76afc EEClass: 71bb164c Size: 116(0x74) bytes File: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll Fields: MT Field Offset Type VT Attr Value Name ... 71d75b24 4001d1c 24 ...em.Net.Connection 0 instance 02cadf4c m_Connection 729c6d34 4001d1d 28 System.Byte[] 0 instance 00000000 m_ReadBuffer 729c560c 4001d1e 4c System.Int32 1 instance 0 m_ReadOffset 729c560c 4001d1f 50 System.Int32 1 instance 0 m_ReadBufferSize 729d05f4 4001d20 18 System.Int64 1 instance -1 m_ReadBytes 729cf91c 4001d21 6a System.Boolean 1 instance 1 m_Chunked 729c560c 4001d22 54 System.Int32 1 instance 0 m_DoneCalled 729c560c 4001d23 58 System.Int32 1 instance 0 m_ShutDown 729c3f60 4001d24 2c System.Exception 0 instance 00000000 m_ErrorException ...
Notice that the m_Connection
instance has the same address as our request connection. Additionally this ConnectStream is not closed (m_DoneCalled == 0
, m_ShutDown == 0
). We can check in the .NET source code that the m_DoneCalled
property is being set in the CallDone
method of the ConnectStream class. This method also dequeues the next request waiting on the connection owned by this ConnectStream instance – in our case it would be our hanging request. Now the timeout cause is clear – we forgot to close (or dispose) the response and thus its underlying ConnectStream.
I created two WinDbg commands to make further investigations faster. The first command to find undisposed ConnectStreams (we are checking if the m_DoneCalled
(offset 0x54) property is not set):
.foreach (addr {!DumpHeap -type System.Net.ConnectStream -short}) { .if (not dwo( addr + 54)) { !do addr; }}
and the second command to find connections with waiting requests (we are checking if size (offset 0xc) of the m_WaitList
(offset 0x5c) is greater than zero):
0:000> !Name2EE System.dll!System.Net.Connection Module: 71b51000 Assembly: System.dll Token: 020004e9 MethodTable: 71d75b24 EEClass: 71b737c4 Name: System.Net.Connection 0:000> .foreach (addr {!DumpHeap -mt 71d75b24 -short}) { .if (dwo(poi( addr + 5c ) + c)) { !do addr } }
I’m using the new HttpClient – am I safe?
Yes, you are. HttpClient is a wrapper over HttpWebRequest and HttpWebResponse and releases properly all the network resources. But system.net constraints and configuration still applies to you – so remember about the connections limit or expect100Continue
parameter. If you don’t know it check what it is, because you probably would like to have it disabled 🙂
Hi Sebastian, this is quite advanced debugging going on. Thanks for the interesting write-up!
Hi Daniel, thank you. I’m glad you liked it 🙂