System.IO.IOException: The server returned an invalid or unrecognized response

[mayconbeserra]

Hi,

I'm having an issue when calling one API which requires certificates. To reproduce we have to execute inside a docker container.

This error doesn't happen on macOS anymore since I migrated to .NET Core 2.1, but it still persists on Docker containers.

Framework: .NET Core 2.1

Docker file uses the following base image: FROM microsoft/dotnet:2.1-runtime

Code as example:

          var cert = new X509Certificate2("./certificate.pfx", "password");
                       
            Console.WriteLine("Has private key: " + cert.HasPrivateKey);
            Console.WriteLine("Chain is valid: " + cert.Verify());
            Console.WriteLine("Version: " + cert.Version);
            handler.ClientCertificates.Add(cert);

            HttpClient client = new HttpClient(handler);

            try
            {
              
                var userpwd = Encoding.ASCII.GetBytes("user:password");
                client.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Basic", Convert.ToBase64String(userpwd));
                client.DefaultRequestHeaders.Add("X-ApplicationName", "APP");
                client.DefaultRequestHeaders.Add("X-TrackingId", "TEST123");
                client.DefaultRequestHeaders.Add("accept", "application/json");
                client.Timeout = TimeSpan.FromSeconds(60);

                client.MaxResponseContentBufferSize = 2147483647;

                var response = await client.GetAsync
                (
                    requestUri: "https://www.myurl.com"
                );

                Console.WriteLine("Result: " + await response.Content.ReadAsStringAsync());
                Console.WriteLine(response.Headers.ToString());
                Console.WriteLine(response.Content.Headers.ToString());
                Console.WriteLine(response.ReasonPhrase);
                
            } catch (Exception ex)
            {
                System.Console.WriteLine("Exception: {0}", ex.ToString());
            }

Error:

Exception: System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The server returned an invalid or unrecognized response.
   at System.Net.Http.HttpConnection.FillAsync()
   at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean foldedHeadersAllowed)
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at app_cert.Program.GetDataAsync2() in /##############/Program.cs:line 112
Inner Exception: System.IO.IOException: The server returned an invalid or unrecognized response.
   at System.Net.Http.HttpConnection.FillAsync()
   at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean foldedHeadersAllowed)
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)

[mayconbeserra]

Result from macOS - Received 1460 bytes

[Microsoft-System-Net-Http-21] (40362448, 55993668, 65204782, WriteToStreamAsync, HttpConnection(HttpConnectionPoolhttps://www.my-api.com:443): Writing 371 bytes.).
[System.Buffers.ArrayPoolEventSource-1] (35016340, 512, 49924125, -1).
[System.Buffers.ArrayPoolEventSource-2] (35016340, 512, 49924125, -1, 2).
[Microsoft-System-Net-Security-1] (SecureChannel#65718035, Encrypt, (System.ReadOnlyMemory<Byte>[371], 371)).
[Microsoft-System-Net-Security-7] (SecureChannel#65718035, Encrypt, System.Byte[]).
[Microsoft-System-Net-Security-2] (SecureChannel#65718035, Encrypt, OK data size:400).
[Microsoft-System-Net-Sockets-1] (Socket#27717712, SendAsync, (AwaitableSocketAsyncEventArgs#26067845)).
[Microsoft-System-Net-Sockets-7] (AwaitableSocketAsyncEventArgs#26067845, LogBuffer, System.Byte[]).
[Microsoft-System-Net-Sockets-2] (Socket#27717712, SendAsync, False).
[System.Buffers.ArrayPoolEventSource-3] (35016340, 512, 49924125).
[Microsoft-System-Net-Http-1] (HttpResponseMessage#64254500, .ctor, (OK)).
[Microsoft-System-Net-Http-2] (HttpResponseMessage#64254500, .ctor, ).
[Microsoft-System-Net-Http-3] (HttpResponseMessage#64254500, RequestMessage, HttpResponseMessage#64254500, HttpRequestMessage#65204782).
[Microsoft-System-Net-Http-1] (HttpConnectionResponseContent#7167227, .ctor, ).
[Microsoft-System-Net-Http-2] (HttpConnectionResponseContent#7167227, .ctor, ).
[Microsoft-System-Net-Http-3] (HttpResponseMessage#64254500, Content, HttpResponseMessage#64254500, HttpConnectionResponseContent#7167227).
[System.Buffers.ArrayPoolEventSource-1] (16294043, 32768, 49924125, -1).
[System.Buffers.ArrayPoolEventSource-2] (16294043, 32768, 49924125, -1, 2).
[Microsoft-System-Net-Sockets-1] (Socket#27717712, ReceiveAsync, (AwaitableSocketAsyncEventArgs#10553853)).
[Microsoft-System-Net-Sockets-2] (Socket#27717712, ReceiveAsync, True).
[System.Threading.Tasks.TplEventSource-26] (32).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 32, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (33).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 33, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (34).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 34, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (35).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 35, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (36).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 36, 2, 0).
[System.Threading.Tasks.TplEventSource-13] (24).
[System.Threading.Tasks.TplEventSource-13] (23).
[System.Threading.Tasks.TplEventSource-13] (31).
[System.Threading.Tasks.TplEventSource-13] (30).
[System.Diagnostics.Eventing.FrameworkEventSource-30] (6537221064).
[System.Diagnostics.Eventing.FrameworkEventSource-31] (6537221064).
[Microsoft-System-Net-Sockets-7] (AwaitableSocketAsyncEventArgs#10553853, LogBuffer, System.Byte[]).
[System.Threading.Tasks.TplEventSource-20] (32, 6538208936).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 32).
[Microsoft-System-Net-Security-1] (SslState#20304321, GetRemainingFrameSize, (System.Byte[32768], 0, 5)).
[Microsoft-System-Net-Security-2] (SslState#20304321, GetRemainingFrameSize, 1484).
[Microsoft-System-Net-Security-1] (SecureChannel#65718035, Decrypt, (System.Byte[32768], 0, 1489)).
[System.Threading.Tasks.TplEventSource-20] (33, 6538210504).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 33).
[Microsoft-System-Net-Http-21] (40362448, 55993668, 65204782, FillAsync, HttpConnection(HttpConnectionPoolhttps://www.my-api.com:443): Received 1460 bytes.).

Result from Container: Received 0 bytes

[Microsoft-System-Net-Http-21] (52243212, 49491130, 27717712, WriteToStreamAsync, HttpConnection(HttpConnectionPoolhttps://www.my-api.com:443): Writing 371 bytes.).
[System.Buffers.ArrayPoolEventSource-1] (54181145, 512, 49924125, 5).
[Microsoft-System-Net-Security-1] (SecureChannel#64828693, Encrypt, (System.ReadOnlyMemory<Byte>[371], 371)).
[Microsoft-System-Net-Security-7] (SecureChannel#64828693, Encrypt, System.Byte[]).
[Microsoft-System-Net-Security-2] (SecureChannel#64828693, Encrypt, OK data size:400).
[Microsoft-System-Net-Sockets-1] (Socket#426867, SendAsync, (AwaitableSocketAsyncEventArgs#31665793)).
[Microsoft-System-Net-Sockets-7] (AwaitableSocketAsyncEventArgs#31665793, LogBuffer, System.Byte[]).
[Microsoft-System-Net-Sockets-2] (Socket#426867, SendAsync, False).
[System.Buffers.ArrayPoolEventSource-3] (54181145, 512, 49924125).
[Microsoft-System-Net-Http-1] (HttpResponseMessage#61879347, .ctor, (OK)).
[Microsoft-System-Net-Http-2] (HttpResponseMessage#61879347, .ctor, ).
[Microsoft-System-Net-Http-3] (HttpResponseMessage#61879347, RequestMessage, HttpResponseMessage#61879347, HttpRequestMessage#27717712).
[Microsoft-System-Net-Http-1] (HttpConnectionResponseContent#3479815, .ctor, ).
[Microsoft-System-Net-Http-2] (HttpConnectionResponseContent#3479815, .ctor, ).
[Microsoft-System-Net-Http-3] (HttpResponseMessage#61879347, Content, HttpResponseMessage#61879347, HttpConnectionResponseContent#3479815).
[System.Buffers.ArrayPoolEventSource-1] (19886533, 32768, 49924125, -1).
[System.Buffers.ArrayPoolEventSource-2] (19886533, 32768, 49924125, -1, 2).
[Microsoft-System-Net-Sockets-1] (Socket#426867, ReceiveAsync, (AwaitableSocketAsyncEventArgs#53447344)).
[Microsoft-System-Net-Sockets-2] (Socket#426867, ReceiveAsync, True).
[System.Threading.Tasks.TplEventSource-26] (32).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 32, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (33).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 33, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (34).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 34, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (35).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 35, 2, 0).
[System.Threading.Tasks.TplEventSource-26] (36).
[System.Threading.Tasks.TplEventSource-10] (1, 0, 36, 2, 0).
[System.Threading.Tasks.TplEventSource-13] (24).
[System.Threading.Tasks.TplEventSource-13] (23).
[System.Threading.Tasks.TplEventSource-13] (31).
[System.Threading.Tasks.TplEventSource-13] (30).
[System.Diagnostics.Eventing.FrameworkEventSource-30] (140204376801192).
[System.Diagnostics.Eventing.FrameworkEventSource-31] (140204376801192).
[System.Threading.Tasks.TplEventSource-20] (32, 140204376786664).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 32).
[System.Threading.Tasks.TplEventSource-20] (33, 140204376789208).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 33).
[Microsoft-System-Net-Http-21] (52243212, 49491130, 27717712, FillAsync, HttpConnection(HttpConnectionPoolhttps://www.my-api.com:443): Received 0 bytes.).

[davidsh]

What server is being used here? The repro code just shows this:

requestUri: "https://www.myurl.com

In order to diagnose this, we'll need a complete repro that can be run.

[mayconbeserra]

Hi @davidsh it's one API from our customer, which I can't share.

The code above has two behaviours - inside a container and on macOS.

I can try to grab more logs if it's required.

We managed to request that API successfully using curl and SOAP-UI.

[davidsh]

Hi @davidsh it's one API from our customer, which I can't share.

Can you reproduce the server/behavior in some way? We don't need the actual customer URL. But we need a server (ASP.NET localhost etc.) that can reproduce the same error that you're getting.

If not, then we'll need more logs and Wireshark (Fiddler could be useful as well) and anything else you think would be useful.

By itself with just this error "The server returned an invalid or unrecognized response." there is not enough information in the trace output above to figure out the root cause.

[mayconbeserra]

Unfortunately, I can't reproduce the server/behaviour. It only happens inside a docker container.

I have added a screenshot, but which logs would be helpful for you? In my second comment, I added some logs from EventListener, do I need to grab more?

[davidsh]

The error "The server returned an invalid or unrecognized response." usually means an HTTP protocol formatting error. Examples could be malformed header/values pairs, missing broken CR-LF at end of headers, etc.

We would need to see the raw response headers coming back from the server to understand if there are "non-standard" responses that the .NET Core HTTP stack can't parse.

[mayconbeserra]

Is there any way to enable logs for getting that information with .NET Core? Or is wireshark/fiddler the only option?

[davidsh]

Is there any way to enable logs for getting that information with .NET Core? Or is wireshark/fiddler the only option?

It looks like you're already using .NET Core logging. The logging will show partial header information but it looks like you didn't post that here in the issue. But generally, wireshark or fiddler is useful.

Without seeing the actual headers coming from the server, it is not possible to diagnose why the HTTP parser is throwing the error.

[mayconbeserra]

Using curl inside the container, the output is below:

Trying 166.fake-ip.0.1...* TCP_NODELAY set* Connected to my-api.com (166.fake-ip.0.1) 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: /etc/ssl/certs/ca-certificates.crt  CApath: /etc/ssl/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 handshake, CERT verify (15):* 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 did not agree to a protocol* Server certificate:*  subject: C=DE; L=City; O=Organisation AG; OU=096; CN=api.corporation.com*  start date: Dec 11 00:00:00 2017 GMT*  expire date: Dec 16 12:00:00 2018 GMT
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert Global CA G2
*  SSL certificate verify ok.
> GET /resource-for-api/identifier HTTP/1.1
> Host: my-api.com
> User-Agent: curl/7.52.1
> Accept: */*
> Authorization: Basic TOKEN
> X-ApplicationName: APP-SRV
> X-TrackingId: 111
>
< HTTP/1.1 200 OK
< Server: Apache-Coyote/1.1
< X-Powered-By: Servlet/3.0
< Set-Cookie: LtpaToken2=RP4XUTvPc3M9KAcS5SUxUzdW9/1B48TuUpHDMIbcTHX554x8hY4en2nylg5UaYeeJ4d+k7in+LNJV6naZD0qV84JG1JKDzBMlnwctokmCq6oll/N5NcJ5tDpFx+N8d4lwLeaKEYRi5jtYLbnlSLcHgh6xA=; Path=/resource/v5; HttpOnly; Domain=my-api.com
< Expires: Thu, 01 Dec 1994 16:00:00 GMT
< Cache-Control: no-cache="set-cookie, set-cookie2"
< Content-Language: en-US
< Content-Type: application/json;charset=utf-8
< Transfer-Encoding: chunked
< Date: Wed, 11 Jul 2018 18:10:06 GMT
<
{"result": { json }}

Does it help?

[karelz]

It tells us how curl behaves, but not what is wrong with .NET Core request. Any reason why Wireshark/Fiddler traces are problematic?
If there is sensitive data, you can inspect the traces yourself.

[mayconbeserra]

Hi @karelz what kind of info do you need? how can I collect them for you?

Looking at the logs provided above, the requested API is returning 0 bytes, and the connection is being reset. Just to be clear, the same code works when running on Windows and MacOS.

[Microsoft-System-Net-Sockets-1] (Socket#426867, ReceiveAsync, (AwaitableSocketAsyncEventArgs#53447344)).
[Microsoft-System-Net-Sockets-2] (Socket#426867, ReceiveAsync, True).
[System.Threading.Tasks.TplEventSource-26] (32).
............................................
............................................
[System.Threading.Tasks.TplEventSource-13] (30).
[System.Diagnostics.Eventing.FrameworkEventSource-30] (140204376801192).
[System.Diagnostics.Eventing.FrameworkEventSource-31] (140204376801192).
[System.Threading.Tasks.TplEventSource-20] (32, 140204376786664).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 32).
[System.Threading.Tasks.TplEventSource-20] (33, 140204376789208).
[System.Threading.Tasks.TplEventSource-11] (1, 0, 33).
[Microsoft-System-Net-Http-21] (52243212, 49491130, 27717712, FillAsync, HttpConnection(HttpConnectionPoolhttps://www.my-api.com:443): Received 0 bytes).

[karelz]

@mayconbeserra the tools are fairly easy to use. Install them and run them on your machine / Docker (Docker may need some special setup to enable it). Run your repro. Save the traces - either inspect them, or send them over. They will capture all network communication, telling us what happened on the wire.

From the logs above, it is not clear if our stack incorrectly thinks there were 0 bytes received, or if there were indeed 0 bytes sent over the wire.

[mayconbeserra]

@karelz which tools? Do you have one example? We’re using https and certificates, which can’t be decrypted. Is there a way to capture it from a container and decrypt that?

Besides that, Running on my machine (macOS / windows) works. Does the framework logs help as well?

[karelz]

which tools? Do you have one example?

The ones mentioned above - Wireshark/Fiddler.

We’re using https and certificates, which can’t be decrypted. Is there a way to capture it from a container and decrypt that?

Let's hope it is going to work on a small repro you have. Hopefully, you can adjust the options otherwise.

Does the framework logs help as well?

The logs you pasted didn't help. Having packet capture logs is IMO the best next step at this moment.

[wfurt]

what is your base container OS @mayconbeserra ? curl often links with providers other than openssl so fat it works is not definitive prove that environment is right. It seems like there is alert message just after server hello when client needs to verify trust.