Socket connection hangs on Linux when buffers aren't read fully before closing connection

[aviviadi]

On windows 10 works perfectly. On ubuntu16 hangs every time. dotnet 1.0.0-preview2-1-003177

command to reproduce (every time) at the following links :

dotnet test src/FastTests -class FastTests.Server.OAuth.CanAuthenticate -verbose

At first I used WebSocket and the connection hanged. Repro every time at:
ravendb/ravendb@1990e41

While thinking this is a websocket problem, I changed the code to use http requests, but it still hangs in the same way. Only when I drains the buffers it passes:
ravendb/ravendb@d8f4aec

The last commit needed only in Linux. In windows it works fine.

My suspect is websocket disconnections timeouts and hangs on linux are related to the above bug, and solving it for http requests will help also with websockets.

[stephentoub]

Can you share an isolated repro that doesn't involve ravendb? On Unix, the Websockets implementation in corefx is entirely separate from the HttpClient/HttpWebRequest, with the former implemented on Sockets and the latter on libcurl, so it's possible but unlikely there's a direct connection.

[aviviadi]

I understand the difference you mentioned, so it might be a different problem in WebSockets, although it hangs in the same point in the same scenario.

I've tried to repro outside the project with no success (also with xunit no success). So no isolated repro is available..

I did try to debug it using Visual Studio 2017 (remote ssh), and also with tcpdump. It showed clearly it sends a response which never reach the target if the read buffer aren't drained.

[stephentoub]

I've tried to repro outside the project with no success

Thanks for trying. How do you know it's a problem with the .NET libs rather than with the ravendb code above it?

[aviviadi]

This is simple client-server request and response. The hang occurs when the above server's BL wants to reply to the client with a response (error string of somekind) before reading the client request body. That's all.. If I drain the read buffers it works. And it works with and without draining the buffer in Windows.

So I think this is narrowing the problem to Linux & Sockets (in parallel xunit tests)

P.S. and the parallel stacks when hanged shows nothing happens from ravendb side except of waiting for the response

[stephentoub]

This is a simple client-server request and response
That's all

But then it should be possible to come up with an isolated repro, right? There are potentially many differences that could be causing an issue and that would explain the difference between it working on Windows and not working on Linux, including for example Windows- or Unix-specific code in ravendb, or fundamental differences at the OS level of how sockets work. And the fact that it repros on two completely different networking stack implementations on Linux (one that uses libcurl and one that uses .NET Sockets) suggests that the problem is either a layer above the .NET libs or a layer below, though like you say the fact that it hangs in exactly the same place could just be coincidence. It'd be very helpful to get an isolated repro.

[stephentoub]

Ah, wait, I looked at your commit. It's dealing with HttpContext. Is that the ASP.NET HttpContext? Meaning this is about working with the ASP.NET libraries?

[aviviadi]

No, it is kestrel's. Ok.. Now we are able to reproduce it without our project : https://gist.github.com/anonymous/af69718f23acf2e4eaff33ff36bf109e

The scenario is that we write from the response without reading the complete data from the request.
Setup a Kesterl app with this code and then run the client code, typically within 3 - 5 iterations, this will cause a hang.

[aviviadi]

Important to note that while this is a repro with plain requests, but we saw the exact same behavior when using web sockets as well, and I strongly suspect that this is related.

[stephentoub]

No, it is kestrel's

Yeah, that's what I meant by ASP.NET; sorry for confusion.

When I said that Websockets and HTTP implementations were unrelated, that was when I thought you were talking about client-side / making outbound requests / using HttpClient or ClientWebSocket (both of which are in the corefx repo). If you're talking about server-side / accepting requests using kestrel, that's an entirely different story.

So, just to be clear, the hang is occurring for you in the server-side of this, correct? Meaning, for example, in the repro you shared, you could be using any client and it would cause a hang in the server?

Assuming yes, sounds like an issue with kestrel (which uses libuv for networking), and we should move the issue to https://github.com/aspnet/kestrelhttpserver.

[aviviadi]

We believe that the issue is on the client side, since we can kill the Kestrel server process and on the client side, it doesn't abort, but have to wait for the full timeout, in this case, the OS already closed all sockets, so I wouldn't expect it.

In addition, tracing via tcpdump shows that the response has been sent to the client.

[stephentoub]

I see. So to summarize:

• The client posts a request to the server.
• The server doesn't read any the request body and instead just sends a response.
• The client then hangs.
• And because the client doesn't disconnect, the server doesn't disconnect / keeps the connection open and assigned to that client.

Have I understood correctly now?

What OS is the client on? What version of libcurl is installed?

[stephentoub]

@aviviadi, does this repro for you if you change the status code in the response from 333 to 200?

I think I may know what's happening. The client starts sending the request. As soon as the request starts to be handled by kestrel, you send back an error code 333. When libcurl gets back that error code, it stops sending any more of the request body. If you look at a trace output from the client, you can see this:

[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_HEADER_IN: HTTP/1.1 333 Unknown).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Size: 22).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Received status line).
[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_HEADER_IN: Date: Tue, 21 Mar 2017 11:37:43 GMT).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Size: 37).
[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_HEADER_IN: Server: Kestrel).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Size: 17).
[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_HEADER_IN: Transfer-Encoding: chunked).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Size: 28).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveHeadersCallback, Size: 2).
[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_TEXT: HTTP error before end of send, stop sending).
[Microsoft-System-Net-Http-6] (2, 101, CurlDebugFunction, CURLINFO_DATA_IN: 1031 bytes).
[Microsoft-System-Net-Http-6] (2, 101, CurlReceiveBodyCallback, Size: 1024).
[Microsoft-System-Net-Http-6] (2, 101, EnsureResponseMessagePublished, Publishing response message).
[Microsoft-System-Net-Http-6] (2, 101, ReadAsync, Buffer: 4096, Offset: 0, Count: 4096).
[Microsoft-System-Net-Http-6] (2, 101, RequestUnpause, ).
[Microsoft-System-Net-Http-6] (2, 0, RequestWakeup, ).
[Microsoft-Diagnostics-DiagnosticSource-2] (HttpHandlerDiagnosticListener, System.Net.Http.Response, System.Object[]).
[Microsoft-System-Net-Http-6] (2, 101, TransferDataToResponseStream, Length: 1024).
[Microsoft-System-Net-Http-6] (2, 101, TransferDataToResponseStream, Completing pending read with 1024 bytes).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait wake-up).
[Microsoft-System-Net-Http-6] (2, 101, HandleIncomingRequests, Type: Unpause).
[Microsoft-System-Net-Http-6] (2, 101, ReadAsync, Buffer: 4096, Offset: 0, Count: 4096).
[Microsoft-System-Net-Http-6] (2, 101, RequestUnpause, ).
[Microsoft-System-Net-Http-6] (2, 0, RequestWakeup, ).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait wake-up).
[Microsoft-System-Net-Http-6] (2, 101, HandleIncomingRequests, Type: Unpause).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).
[Microsoft-System-Net-Http-6] (2, 0, WaitForWork, Wait timeout).

In particular that "HTTP error before end of send, stop sending)." appears to be key. And if you look at a corresponding log on the server side, you see output like this:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 0.1799ms 333
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST http://localhost:5000/ text/plain; charset=utf-8 1152
info: Microsoft.AspNetCore.Server.Kestrel[17]
      Connection id "0HL3G9QO0VQRK" bad request data: "Unexpected end of request content."
Microsoft.AspNetCore.Server.Kestrel.BadHttpRequestException: Unexpected end of request content.

so it appears that when the race condition causes the client to stop sending the body, it and the server then get into a deadlock waiting for the other to finish.

If I change the response code to 200 instead of 333, the hang goes away.

This would also explain why you don't see the issue on Windows: for better or worse, the WinHTTP implementation sends the full body of the request before processing any of the response.

[aviviadi]

Yes you've understood correctly :) (I never requested you to debug ravendb...)

OS : ubuntu 16.04 (kernel 4.4), curl 7.47

[aviviadi]

I tried with returning 201 and it works. 500 or other non IsSuccessfull rc doesn't

[stephentoub]

@aviviadi, from what I can see from the trace as well, it appears chunked transfer-encoding is being used, and the client isn't receiving the necessary 0-length chunk at the end. Do you see that in your tcpdump trace? If it's not being received (for the request that hangs), that would explain why the client is sitting there waiting. And maybe that's not being sent because the server incurs a BadHttpRequestException exception due to it issuing an error code that causes the client to stop sending the request?