Unknown cURL error when using HTTP/2 to connect to api.push.apple.com

[yaakov-h]

Using .NET Core 1.1 on macOS "Sierra" 10.12.2 (build 16C67).

When using System.Net.Http.HttpClient to try connect via HTTP/2 to api.push.apple.com, there's some unexplained cURL error - see below.

The exception is not descriptive enough to attempt to troubleshoot, and as the connection is encrypted, I cannot examine it and compare the transmissions to a working reference implementation.

Repro code:

```c# using System; using System.Net.Http; using System.Threading.Tasks; namespace ConsoleApplication { public class Program { public static int Main(string[] args) => MainAsync(args).GetAwaiter().GetResult(); static async Task MainAsync(string[] args) { try { using (var client = new HttpClient()) { var request = new HttpRequestMessage(HttpMethod.Post, "https://api.push.apple.com/3/device/AAA"); request.Version = new Version(2, 0); var response = await client.SendAsync(request); Console.WriteLine($"HTTP Status Code: {response.StatusCode}"); Console.WriteLine(await response.Content.ReadAsStringAsync()); } return 0; } catch (Exception ex) { WriteExceptionRecursive(ex); return -1; } } static void WriteExceptionRecursive(Exception ex) { if (ex.InnerException != null) { WriteExceptionRecursive(ex.InnerException); } Console.WriteLine($"{ex.GetType().Name}: {ex.Message}"); Console.WriteLine(ex.StackTrace); Console.WriteLine(); } } } ```

Output:

[04:13pm yaakov@Expression:/tmp/netcore_apple] dotnet run
Project netcore_apple (.NETCoreApp,Version=v1.1) will be compiled because inputs were modified
Compiling netcore_apple for .NETCoreApp,Version=v1.1

Compilation succeeded.
    0 Warning(s)
    0 Error(s)

Time elapsed 00:00:01.4441779

CurlException: Failure when receiving data from the peer
   at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
   at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)

IOException: The read operation failed, see inner exception.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at System.Net.Http.StreamToStreamCopy.<CopyAsyncAnyStreamToAnyStreamCore>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   at System.Net.Http.HttpContent.<LoadIntoBufferAsyncCore>d__48.MoveNext()

HttpRequestException: Error while copying content to a stream.
   at System.Net.Http.HttpContent.<LoadIntoBufferAsyncCore>d__48.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at ConsoleApplication.Program.<MainAsync>d__1.MoveNext() in /private/tmp/netcore_apple/Program.cs:line 21

For reference, a build of the cURL command-line client that supports HTTP/2 provides the following output:

``` [04:21pm yaakov@Expression:/tmp/netcore_apple] /usr/local/Cellar/curl/7.52.1/bin/curl -v --http2 -X POST https://api.push.apple.com/3/device/AAA * Trying 17.188.160.207... * TCP_NODELAY set * Connected to api.push.apple.com (17.188.160.207) port 443 (#0) * ALPN, offering h2 * ALPN, offering http/1.1 * Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH * successfully set certificate verify locations: * CAfile: /usr/local/etc/openssl/cert.pem CApath: /usr/local/etc/openssl/certs * TLSv1.2 (OUT), TLS header, Certificate Status (22): * TLSv1.2 (OUT), TLS handshake, Client hello (1): * TLSv1.2 (IN), TLS handshake, Server hello (2): * TLSv1.2 (IN), TLS handshake, Certificate (11): * TLSv1.2 (IN), TLS handshake, Server key exchange (12): * TLSv1.2 (IN), TLS handshake, Request CERT (13): * TLSv1.2 (IN), TLS handshake, Server finished (14): * TLSv1.2 (OUT), TLS handshake, Certificate (11): * TLSv1.2 (OUT), TLS handshake, Client key exchange (16): * TLSv1.2 (OUT), TLS change cipher, Client hello (1): * TLSv1.2 (OUT), TLS handshake, Finished (20): * TLSv1.2 (IN), TLS change cipher, Client hello (1): * TLSv1.2 (IN), TLS handshake, Finished (20): * SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 * ALPN, server accepted to use h2 * Server certificate: * subject: CN=api.push.apple.com; OU=management:idms.group.533599; O=Apple Inc.; ST=California; C=US * start date: Aug 28 19:03:46 2015 GMT * expire date: Sep 26 19:03:46 2017 GMT * subjectAltName: host "api.push.apple.com" matched cert's "api.push.apple.com" * issuer: CN=Apple IST CA 2 - G1; OU=Certification Authority; O=Apple Inc.; C=US * SSL certificate verify ok. * Using HTTP2, server supports multi-use * Connection state changed (HTTP/2 confirmed) * Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0 * Using Stream ID: 1 (easy handle 0x7fd42980b000) > POST /3/device/AAA HTTP/1.1 > Host: api.push.apple.com > User-Agent: curl/7.52.1 > Accept: */* > * Connection state changed (MAX_CONCURRENT_STREAMS updated)! < HTTP/2 403 < apns-id: 1AD32888-F1A3-3494-BCBD-2783E02F7AD3 < * Curl_http_done: called premature == 0 * Connection #0 to host api.push.apple.com left intact {"reason":"MissingProviderToken"} ```

[yaakov-h]

Looking at a packet capture, it appears that there is no ALPN portion of the TLS Client Hello sent by .NET Core. Is there some cURL prerequisite I need to have installed?

[keichinger]

Maybe it's related -- I haven't checked but I could try tomorrow -- but there are similar(or the same?) problems with other languages such as PHP. The problem here is that Apple is supplying an outdated/older version of OpenSSL which needs to be updated manually. And since we've updated OpenSSL, we also need to recompile cURL to point it to our new version of OpenSSL.

Just run the following:

$ brew rm curl # you may or may not have it installed via brew
$ brew update
$ brew install --with-openssl curl

[yaakov-h]

The version of cURL I have from Homebrew does support HTTP/2. I used the following command earlier:

$ brew reinstall curl --with-openssl --with-nghttp2

[yaakov-h]

Although...

This formula is keg-only, which means it was not symlinked into /usr/local.

macOS already provides this software and installing another version in
parallel can cause all kinds of trouble.

Generally there are no consequences of this for you. If you build your
own software and it requires this formula, you'll need to add to your
build variables:

    LDFLAGS:  -L/usr/local/opt/curl/lib
    CPPFLAGS: -I/usr/local/opt/curl/include
    PKG_CONFIG_PATH: /usr/local/opt/curl/lib/pkgconfig

==> Summary
🍺  /usr/local/Cellar/curl/7.52.1: 389 files, 2.8M, built in 1 minute 48 seconds

[karelz]

@cH40z-Lord do you have any reference to problems in other languages? If that's true, the issue is likely unrelated to .NET Core - unless we need to update our prereqs to require special curl install ...

[keichinger]

@karelz I'm not 100% sure if it's related, but we had a similar issue at work with cURLing into an SSL protected HTTP/2 API with PHP. We solved it by re-installing cURL with a local installation of OpenSSL, just like mentioned http://stackoverflow.com/a/26538127/2690438 Though it's entirely possible that it's a different problem and I'm wrong.

[karelz]

Thanks for the info @cH40z-Lord cc @Priya91

[yaakov-h]

I did some further testing by using the .NET Core Docker container, i.e. running inside of docker run -it microsoft/dotnet:latest

Running the repro case in the original post above yields the following output:

root@d982f00dd8ef:/hwapp# dotnet restore
log  : Restoring packages for /hwapp/project.json...
log  : Writing lock file to disk. Path: /hwapp/project.lock.json
log  : /hwapp/project.json
log  : Restore completed in 876ms.
root@d982f00dd8ef:/hwapp# dotnet run
Project hwapp (.NETCoreApp,Version=v1.1) will be compiled because expected outputs are missing
Compiling hwapp for .NETCoreApp,Version=v1.1

Compilation succeeded.
    0 Warning(s)
    0 Error(s)

Time elapsed 00:00:01.7345728

HTTP Status Code: OK
@@�HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 504f5354202f332f6465766963652f41414120485454502f

Apple send that in response to a HTTP/1 request. The decoded hex dump is POST /3/device/AAA HTTP/.

This suggests that cURL is working as intended, though it would appear that the Docker container does not have HTTP/2.0 support in the version of libcurl that it is using.

Two points to note here:

1. When running on macOS, there is that exception above when copying between streams. When running on Linux/Docker, there is no such exception.
2. The .NET Core runtime appears to not ship with support for HTTP/2 for macOS or Linux. (Under Windows, I believe this is dictated by WinHTTP and requires Windows 10 >= 1067.)

Is this the correct place to also handle the second point, and if not, where can I file the bug for that?

Thanks.

[Priya91]

@yaakov-h I did some investigation on this today, and mostly followed the instructions on this thread, just ramping up in this area. Setup curl with http2 following the docs on OSX, and using your repro, I got a SSL connect error with the apple server, probably because the right certificates are not found. So used your repro with google.com, and printed the http version used. From .NET Core, it reports the curl version being used is HTTP/1.1.

                using (var client = new HttpClient())
                {    
                    var request = new HttpRequestMessage(HttpMethod.Get, "https://www.google.com/");
                    request.Version = new Version(2, 0);

                    var response = await client.SendAsync(request);
                    Console.WriteLine($"HTTP Status Code: {response.StatusCode}");
                    Console.WriteLine($"HTTP Version: {response.Version}");
                }

output being,

HTTP Status Code: OK
HTTP Version: 1.1

It only leads me to conclude that the version of curl in /usr/local/bin/curl is not being used. The native header files in .NET Core, is coming from /usr/include/curl/curl.h. You can clone this repo and modify sources under src/Native/Unix/System.Net.Http.Native to use the header files of this curl install (/usr/local/opt/curl/include/curl/curl.h) to make your custom .NET Core binaries find these newer curl dylibs under /usr/local/libs. You may have to also modify the interop APIs, if there are newer surface area for http2.

.NET Core will not support this, until OS X ships this version of curl by default.

If this issue happens with HTTP/1.1 from default curl install on OSX then we can investigate this further, else there is nothing to be done from .NET Core.

[yaakov-h]

There appears to already be some support in the interop APIs for HTTP/2, so it would appear that if present it would work, if not present it will naturally not work.

Does .NET Core not wish to ship it's own dependencies (.NET Core, OpenSSL, etc.)? It appears to currently be relying on globally installed software, so much so that the installation instructions for OpenSSL require the user to use Homebrew to install and symlink new libssl and libcrypto dylibs.

If so, I'll file a radar with Apple, but where would be the appropriate location to file a bug that the .NET Core Docker container does appear to not ship with an HTTP/2-compatible version of libcurl?

However, that's all regarding getting HTTP/2 actually working. I would expect that without HTTP/2 support, .NET Core / curl would simply fall back to HTTP/1.1.

If so, why do I get the HttpRequestException/IOException/CurlException chain above? That was from a .NET Core installation using the macOS default version of libcurl - the custom curl version I have from Homebrew isn't symlinked into /usr/local/whatever, it only exists in /usr/local/Cellar/curl.

[Priya91]

If so, why do I get the HttpRequestException/IOException/CurlException chain above?

The .NET exception is thrown due to the curl error, could you try the post method to that uri using default curl install on your osx machine, and paste the output here? The one you've included in the description is with the custom curl install.

[yaakov-h]

[06:03pm yaakov@Expression:~] which curl
/usr/bin/curl
[06:03pm yaakov@Expression:~] curl --version
curl 7.51.0 (x86_64-apple-darwin16.0) libcurl/7.51.0 SecureTransport zlib/1.2.8
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz UnixSockets 
[06:03pm yaakov@Expression:~] curl -v --http2 -X POST https://api.push.apple.com/3/device/AAA
curl: (1) Unsupported protocol
[06:03pm yaakov@Expression:~] curl -v -X POST https://api.push.apple.com/3/device/AAA
*   Trying 17.188.166.96...
* TCP_NODELAY set
* Connected to api.push.apple.com (17.188.166.96) port 443 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate: api.push.apple.com
* Server certificate: Apple IST CA 2 - G1
* Server certificate: GeoTrust Global CA
> POST /3/device/AAA HTTP/1.1
> Host: api.push.apple.com
> User-Agent: curl/7.51.0
> Accept: */*
> 
* SSLRead() return error -9806
* Curl_http_done: called premature == 1
* Closing connection 0
curl: (56) SSLRead() return error -9806
@@?HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 504f5354202f332f6465766963652f41414120485454502f[06:03pm yaakov@Expression:~] 

[Priya91]

Does .NET Core not wish to ship it's own dependencies (.NET Core, OpenSSL, etc.)? It appears to currently be relying on globally installed software, so much so that the installation instructions for OpenSSL require the user to use Homebrew to install and symlink new libssl and libcrypto dylibs.

cc @karelz Do you have more info on the ship story?

but where would be the appropriate location to file a bug that the .NET Core Docker container does appear to not ship with an HTTP/2-compatible version of libcurl?

It would be this repo dotnet/dotnet-docker

[Priya91]

@yaakov-h From your output

* SSLRead() return error -9806
* Curl_http_done: called premature == 1
* Closing connection 0
curl: (56) SSLRead() return error -9806

It is the same curl (56) error that's thrown in .NET Core as well.

[yaakov-h]

That -9806 appears to be an Apple OSStatus value of errSSLClosedAbort ("The connection closed due to an error."). Can we somehow get that error text from macOS and put it into the exception message, rather than just the generic "Failure when receiving data from the peer"?

[Priya91]

Can we somehow get that error text from macOS and put it into the exception message, rather than just the generic "Failure when receiving data from the peer"?

Looking at the implementation in .NET Core, .NET just calls the curl API, curl_multi_info_read which may call into OS SSLRead function. .NET gets the error code from this Curl API, so I'm not sure how .NET can be made aware of some info abstracted by curl.

[Priya91]

The issue has been addressed and followup info provided, closing the issue.

[yaakov-h]

If I use a newer version of libcurl by setting export DYLD_LIBRARY_PATH=/usr/local/opt/curl/lib, I get a different exception instead:

System.Net.Http.HttpRequestException: The server returned an invalid or unrecognized response.
   at System.Net.Http.CurlResponseHeaderReader.ReadStatusLine(HttpResponseMessage response)
   at System.Net.Http.CurlHandler.MultiAgent.CurlReceiveHeadersCallback(IntPtr buffer, UInt64 size, UInt64 nitems, IntPtr context)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at ConsoleApplication.Program.<MainAsync>d__7.MoveNext() in /Users/yaakov/Development/Projects/Active/BuzzerTest/Program.cs:line 78
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at ConsoleApplication.Program.Main(String[] args) in /Users/yaakov/Development/Projects/Active/BuzzerTest/Program.cs:line 27

Are there any switches, environment variables etc. that I can set in order to see what is going on under the hood, particularly the calls to EventSourceTrace within corefx?

Failing that, how can I debug corefx? I've found documents for coreclr, but don't see any for corefx.

I'd like to be able to get this working one way or another, even if that means modifying corefx (and filing a pull request).

[karelz]

Does .NET Core not wish to ship it's own dependencies (.NET Core, OpenSSL, etc.)? It appears to currently be relying on globally installed software, so much so that the installation instructions for OpenSSL require the user to use Homebrew to install and symlink new libssl and libcrypto dylibs.

We do not want to reship 3rd party SW unless we have to - it comes with the burden of security patching those components, etc. For OpenSSL, we are working on migration to Apple crypto APIs due to the feedback from our Mac users - sadly there is no way to rely on OpenSSL library on Mac without additional hassle. Disclaimer: I am not Mac expert/user, so if you feel my answers are incorrect, please bear with me. I'll be happy to loop in experts on the topic to provide more details if required. My knowledge in the area is only high-level, relying mostly on Windows SW distribution model.

[Priya91]

We have unix debug instructions here, and event source docs here

[Priya91]

@yaakov-h I would suggest verifying with curl first, to determine that it's a .NET problem, before you go down chasing application bug in .NET.

[yaakov-h]

@Priya91 Thanks. The curl command-line app works as expected, so it's mostly likely a .NET problem. I'll try to prove it first with a small program using libcurl directly, though.

Interestingly enough the hack above with DYLD_LIBRARY_PATH results in an error parsing the response, but the request worked - my test script contacted the Apple servers which sent a Push Notification to my device. That would also point towards either a bug in .NET, or unexpected behaviour from an untested version of libcurl, which AFAICT should both boil down to the same thing - changes to corefx to handle it.

The event source documentation is only for Windows, and event sources are not mentioned in the Unix instructions. Is there no event source equivalent for nix systems? (If so, why does the nix code use event sources at all?)

[Priya91]

Is there no event source equivalent for *nix systems?

@vancem @stephentoub Do you guys know how to access the event source logs on Unix?

[MichaelSimons]

Per the issue pointed out that our dotnet-docker images do not support HTTP/2, is there guidance on what the setup is to support http/2 (specifically for Debian)? Our Docker images have libcurl3/now 7.38.0-4+deb8u5 amd64 [installed,local]. The version of curl installed does not support http2. Is it sufficient to follow the steps to configure curl with http2 support?

[yaakov-h]

I believe so. Installing curl from Homebrew on macOS didn't have HTTP/2 support out of the box, it required installing with the --with-nghttp2 flag.

As such those steps look like they should be correct, but I'd have to try them to know for certain.

[MichaelSimons]

I did verify running these steps to configure curl with http2 support on Debian are sufficient to get the aforementioned sample to work.

[flo8]

We also encountered this bug in a console app with .Net Core 1.1 (netcoreapp1.1) in a standalone application running on Ubuntu 16.04.2 LTS (GNU/Linux 4.4.0-70-generic x86_64) the problem seems to happen randomly.

I posted more details about the issue here: https://github.com/dotnet/corefx/issues/9357

Could this be related?

[yaakov-h]

What you've posted suggests a different issue, but without the ability to reproduce it's hard to say for certain.

[flo8]

@yaakov-h Yes we will try to reproduce it but it seems to happen very randomly and rarely for the moment...