.NET Core 2.1 HttpClient hangs on first SSL call on Mac OS

[razfriman]

I stumbled upon this while trying to connect to Microsoft Cognitive Services api in .NET Core 2.1. The first call made using HttpClient hangs and takes about 3-6 seconds. Any calls made on the same HttpClient after this finish at a normal speed (~200ms).

This bug seems to be limited to MacOS/Unix and does NOT affect Windows.

Settings the following switch "solves" the issue, but I suspect something is wrong inside the SocketsHttpHandler for MacOS/Unix.

AppContext.SetSwitch("System.Net.Http.UseSocketsHttpHandler", false);

using System;
using System.Diagnostics;
using System.Net.Http;
using System.Threading.Tasks;

namespace HttpClientTest
{
    public static class Program
    {
        public static async Task Main(string[] args)
        {
            await MakePostCall();
            await MakePostCall();
            await MakePostCall();

            Console.WriteLine("Disable: System.Net.Http.UseSocketsHttpHandler");
            AppContext.SetSwitch("System.Net.Http.UseSocketsHttpHandler", false);

            await MakePostCall();
            await MakePostCall();
            await MakePostCall();

            Console.WriteLine("Done");
        }

        private static async Task MakePostCall()
        {
            var uri = $"http://api.cognitive.microsoft.com/sts/v1.0/issueToken";

            using (var client = new HttpClient())
            {
                var sw = Stopwatch.StartNew();
                await client.PostAsync(uri, new StringContent(""));
                sw.Stop();
                Console.WriteLine($"{sw.ElapsedMilliseconds}ms");
            }
        }
    }
}

Program Output

2396ms
5244ms
5246ms
Disable: System.Net.Http.UseSocketsHttpHandler
270ms
236ms
236ms
Done

[karelz]

@wfurt can you please try if it repros? This seems suspicious.

[wfurt]

My numbers are different but I can see first request being significantly longer:
OSX 10.13.4

155ms
53ms
44ms
Disable: System.Net.Http.UseSocketsHttpHandler
64ms
47ms
42ms
Done

Just for comparisons on Ubuntu 16.04:

307ms
50ms
77ms
Disable: System.Net.Http.UseSocketsHttpHandler
127ms
59ms
53ms
Done

Note that first request is always long, what is different is the magnitude.

Note that posted numbers do not match description. Posted repro has no SSL and second and third try are slower than first.

Also note that old OSX handler was unusual in a sense that there is singleton behind the scenes.
Disposing and creating new HttpClient() really does not do much as the underlying curl context still exist.

now as a experiment, I did run the handlers in different order, e.g. legacy first and new second:

Disable: System.Net.Http.UseSocketsHttpHandler
168ms
67ms
42ms
Enable: System.Net.Http.UseSocketsHttpHandler
106ms
43ms
44ms
Done

and than run identical test again:

Disable: System.Net.Http.UseSocketsHttpHandler
74ms
42ms
42ms
Enable: System.Net.Http.UseSocketsHttpHandler
98ms
44ms
44ms
Done

I'm wondering if name resolution is part of the culprit. First call will always be slower as we need to initialize crypto and do DNS lookup. The question is what is reasonable.

[stephentoub]

First call will always be slower as we need to initialize crypto and do DNS lookup.

The first call also needs to establish a connection, which is then pooled for subsequent requests to use.

[wfurt]

The new connection should be common problem for both handlers, right? That may not be true for OSX singleton but I see first request bit slower even on Linux.

[stephentoub]

The new connection should be common problem for both handlers, right? That may not be true for OSX singleton but I see first request bit slower even on Linux.

Sure, but the costs of setting up a connection can differ.

[razfriman]

From my experimentation the issue seemed to be the SSL handshake hanging

Can you try to repro it using the same url I used? (or another url with SSL)

[karelz]

@razfriman your repro uses http URL, not https. Either you modified the repro on your machine, or there is no SSL handshake.
BTW: @wfurt tried both (http and https on your URL). I asked him to collect more data.

The data from top post are suspicious - they show 2nd and 3rd SocketsHttpClient instances to be significantly slower (5.2s) than the 1st one (2.4s). It would be best to collect more data from isolated process runs and do basic statistical analysis.

[razfriman]

@karelz I didn't notice that, I must have modified the repro on my many attempts.

I even tried running this same example in a linux docker container microsoft/dotnet:2.1-runtime running the same code and got even stranger results (All requests taking 15,000ms).

 docker run httptest
15516ms
15422ms
15434ms
Disable: System.Net.Http.UseSocketsHttpHandler
15616ms
15466ms
15489ms
Done

I am still stumped.

Perhaps you could chalk this up to me being in Australia and the server being located in USA?
But I am on 100mbps connection, so I imagine that wouldn't affect it this drastically.

[karelz]

@razfriman if you see now 15s turnaround on all requests, I would suggest to look at network traces (Wireshark/Fiddler) - they will tell you how long which part takes.

[davidsh]

Perhaps you could chalk this up to me being in Australia and the server being located in USA?
But I am on 100mbps connection, so I imagine that wouldn't affect it this drastically.

Being on a 100mps connection only helps you locally in your local network (at home/work) and to the next "hop" (your ISP). Latency matters a lot especially with big distances such as across the globe (Australia - US) and will contribute to overall long periods for an HTTP request/response to complete especially for UDP (DNS) packets to get sent/received. Longer latency will contribute to them getting lost. And TCP can be affected as well, requiring multiple re-tries of packets.

Interesting article: https://www.crucial.com.au/blog/2013/04/05/ping-the-world/

It would be better if you could localize the repro so that client and server were relatively "close" in distance and then get some numbers.

[stephentoub]

Could you try running this:

using System;
using System.Diagnostics;
using System.Net;
using System.Net.Sockets;
using System.Text;
using System.Threading.Tasks;

class Program
{
    static async Task Main()
    {
        var sw = Stopwatch.StartNew();
        var entry = await Dns.GetHostEntryAsync("api.cognitive.microsoft.com");
        Console.WriteLine($"DNS: {string.Join<IPAddress>(", ", entry.AddressList)}. {sw.Elapsed}.");

        foreach (var addr in entry.AddressList)
        {
            using (var s = new Socket(SocketType.Stream, ProtocolType.Tcp))
            {
                try
                {
                    sw.Restart();
                    await s.ConnectAsync(addr, 80);
                    Console.WriteLine($"{addr}. Connected. {sw.Elapsed}");

                    await s.SendAsync(Encoding.ASCII.GetBytes($"POST /sts/v1.0/issueToken HTTP/1.1\r\nHost: api.cognitive.microsoft.com\r\nContent-Length: 0\r\n\r\n"), SocketFlags.None);
                    s.Shutdown(SocketShutdown.Send);
                    Console.WriteLine($"Sent request. {sw.Elapsed}");

                    var buffer = new byte[1024];
                    int count = 0;
                    while (true)
                    {
                        int received = await s.ReceiveAsync(buffer, SocketFlags.None);
                        if (received == 0) break;
                        count += received;
                        Console.WriteLine($"Received {received} bytes {Encoding.ASCII.GetString(buffer, 0, received)}. {sw.Elapsed}");
                    }

                    Console.WriteLine("Done");
                    break;
                }
                catch (Exception exc)
                {
                    Console.WriteLine($"{addr} Failed: " + exc);
                }
            }
        }
    }
}

and sharing the output?

[razfriman]

Sure, here it is

DNS: 52.230.30.206. 00:00:05.1070740.
52.230.30.206. Connected. 00:00:00.2311070
Sent request. 00:00:00.2323990
Received 339 bytes HTTP/1.1 404 Resource Not Found
Content-Length: 54
Content-Type: application/json
apim-request-id: 21ad7de9-59dd-41e3-bd18-1126524b3697
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
x-content-type-options: nosniff
Date: Tue, 12 Jun 2018 21:30:51 GMT

{ "statusCode": 404, "message": "Resource not found" }. 00:00:00.4068570
Done

[stephentoub]

Running almost instantly

Except the DNS lookup took over 5 seconds: "00:00:05.1070740".

[razfriman]

@stephentoub - You are correct, I didn't notice that number.
The DNS seems to be the issue. I forced my computer to point to Google DNS and the issue seems to have resolved.

Additionally, from the original code I posted, they are both running identically.

Thanks for the help

DNS: 52.179.13.227. 00:00:00.0646960.
52.179.13.227. Connected. 00:00:00.2737860
Sent request. 00:00:00.2749880
Received 339 bytes HTTP/1.1 404 Resource Not Found
Content-Length: 54
Content-Type: application/json
apim-request-id: 0a6ab1d0-d76a-45ba-bdb5-9364566ddec8
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
x-content-type-options: nosniff
Date: Tue, 12 Jun 2018 21:34:03 GMT

{ "statusCode": 404, "message": "Resource not found" }. 00:00:00.5534880
Done

1282ms
1200ms
1227ms
Disable: System.Net.Http.UseSocketsHttpHandler
1246ms
1211ms
1233ms
Done

[karelz]

Thanks for tracking it down. Closing as there is nothing actionable left AFAIK.