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:
System.Net Verbose: 0 : [2764] HttpWebRequest#60068066::HttpWebRequest(http:
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:
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:
System.Net Verbose: 0 : [2764] HttpWebRequest#26753075::HttpWebRequest(http:
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), e.g.:
<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 on 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 = <no data>
millisecondsTimeout = <no data>
hasThreadAffinity = <no data>
exitContext = <no data>
LOCALS:
<no data>
00eaed5c 728b64c4 System.Threading.WaitHandle.WaitOne(Int32, Boolean)
PARAMETERS:
this = <no data>
millisecondsTimeout = <no data>
exitContext = <no data>
00eaed70 71cea6b1 System.Net.LazyAsyncResult.WaitForCompletion(Boolean)
PARAMETERS:
this (0x00eaed70) = 0x02d9ca5c
snap = <no data>
LOCALS:
<no data>
0x00eaed74 = 0x00000001
<no data>
<no data>
00eaeda0 71cfe3cf System.Net.Connection.SubmitRequest(System.Net.HttpWebRequest, Boolean)
PARAMETERS:
this (0x00eaeda8) = 0x02c9c204
request (0x00eaeda4) = 0x02d84a28
forcedsubmit = <no data>
LOCALS:
0x00eaedbc = 0xffffffff
0x00eaedb8 = 0x00000000
<no data>
<no data>
<no data>
<no data>
0x00eaedb0 = 0x00000001
<no data>
<no data>
00eaede8 71cfcf3b System.Net.ServicePoint.SubmitRequest(System.Net.HttpWebRequest, System.String)
PARAMETERS:
this = <no data>
...
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. :)
Filed under: CodeProject, Diagnosing network issues in .NET 
