Search code examples
dotnet-httpclientsystem.net

System.Net.HttpClient - Unexplained timeout when calling GetAsync


We have an ASP.NET application (.NET 4.5.2) that's hosted by IIS 8.5. It makes calls into several web services that are hosted on the same machine. We use HttpClient to make the calls to the web services and we use the FQDN of the server to address the web services. There may be several users connected to the server at any given time.

We're seeing somewhat inexplicable timeouts in the application and trying to understand how we can fix it. We've isolated the issue in the System.Net trace but I don't know how to map this to what might be happening in the app.

We always see a trace that looks roughly like this:

System.Net Verbose: 0 : [7040] ServicePoint#54409111::ServicePoint([fqdn]:443)
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net Information: 0 : [7040] Associating HttpWebRequest#63284140 with ServicePoint#54409111
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net Information: 0 : [7040] Associating Connection#66464819 with HttpWebRequest#63284140
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Socket#15069449::Socket(AddressFamily#2)
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Exiting Socket#15069449::Socket() 
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Socket#36384690::Socket(AddressFamily#23)
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Exiting Socket#36384690::Socket() 
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] DNS::TryInternalResolve([fqdn])
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Socket#36384690::BeginConnectEx()
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Socket#36384690::InternalBind([::]:0#-1630021378)
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Exiting Socket#36384690::InternalBind() 
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [7040] Exiting Socket#36384690::BeginConnectEx()    -> ConnectOverlappedAsyncResult#20281278
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net Verbose: 0 : [7040] Exiting HttpWebRequest#63284140::BeginGetResponse()  -> ContextAwareResult#61049080
    DateTime=2018-07-31T14:19:39.8579341Z
System.Net.Sockets Verbose: 0 : [1988] Socket#36384690::EndConnect(ConnectOverlappedAsyncResult#20281278)
    DateTime=2018-07-31T14:20:00.8591809Z
System.Net.Sockets Error: 0 : [1988] Socket#36384690::UpdateStatusAfterSocketError() - TimedOut
    DateTime=2018-07-31T14:20:00.8591809Z
System.Net.Sockets Error: 0 : [1988] Exception in Socket#36384690::EndConnect - A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond [fe80::10f8:605a:8a44:5f1e%12]:443.
    DateTime=2018-07-31T14:20:00.8591809Z

In every case where we have this timeout occur we see this call sequence: DNS::TryInternalResolve and then to: Socket#########::InternalBind([::]:0#-1630021378)

In a successful connection we see: ::InternalBind(0.0.0.0:0#0) with no call to resolve the DNS

The weird thing is that the application never sees any errors. The call to HttpClient just seems to take a long time.

Anyone know what's happening here or if there's more debugging information I can turn on to learn more?


Solution

  • A couple of thoughts -

    • check IPv6 is disabled on the host machine. It sounds like initial DNS lookups (perhaps occurring when a cached record TTL expires) are sometimes attempted via IPv6 which may have a bogus DNS server associated with it (check your IP config and also test that ping {fqdn} -6 actually works.....or as said above just disable it)

    • DNS might be a red herring here and the real problem is that you’re hitting a maximum connections limit. There are many places that this could be occurring but two easy things to check - First make sure you’re not recreating/disposing your HttpClient for each call....it should be static. Second, if you have more than 100 tcp connections being made per second consider increasing the ServicePointManager max connections limit