HTTP 1.0 request might return empty response

[jacksonrayhamilton]

If I send an HTTP 1.0 request, according to specification, I can expect the server to automatically close the connection at the end unless both the client and server send Connection: keep-alive.

If my server’s response does not include Transfer-Encoding: chunked and it does not have a Content-Length and it does not include Connection: close, then an HTTP 1.0 request will erroneously be blank due to this line: https://github.com/ysbaddaden/prax.cr/blob/e9cd772414dff2fd142dcdc8fbe95cc886fcbfe3/src/prax/middlewares/proxy_middleware.cr#L37

How do we fix this? I’ve tried this:

diff --git a/src/prax/middlewares/proxy_middleware.cr b/src/prax/middlewares/proxy_middleware.cr
index 8274ea8..d18fc44 100644
--- a/src/prax/middlewares/proxy_middleware.cr
+++ b/src/prax/middlewares/proxy_middleware.cr
@@ -31,10 +31,8 @@ module Prax
           stream_chunked_response(server, client)
         elsif (len = response.content_length) > 0
           copy_stream(server, client, len)
-        elsif response.header("Connection") == "close"
-          copy_stream(server, client)
         else
-          # TODO: read until EOF / connection close?
+          copy_stream(server, client)
         end
       end

However, for the very first request I send to a Rack server, it hangs forever even after the server starts. The second request goes through. (???) Any ideas?

[ysbaddaden]

Is there a response sent? How does the server behaves, is it closing the connection after sending a response, which Prax could act upon?

[jacksonrayhamilton]

Hey @ysbaddaden, I tried tackling this again, but to no avail. I’ll share my progress with you or whoever else may stumble upon this issue.

I’ve added a failing test for this at: https://github.com/jacksonrayhamilton/prax.cr/commit/5ba56b9465c8d083aa8fb45ee52f786027753624

I also committing a change to ProxyMiddleware#proxy to try to send the response body, plus some tracing code, here: https://github.com/jacksonrayhamilton/prax.cr/commit/9d7e084e7f0dc600dc017c3745d2cb9b872e566b

I’m compiling Prax from the above tracing commit and running it from the prax.cr directory like so:

./bin/prax start --hosts test/hosts/ -V

If I send an HTTP 1.1 request with cURL, it works:

$ curl http://example.localhost --verbose --http1.1
* Expire in 0 ms for 6 (transfer 0x561fecec8900)
…
* Expire in 2 ms for 1 (transfer 0x561fecec8900)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149996 ms for 3 (transfer 0x561fecec8900)
* Expire in 200 ms for 4 (transfer 0x561fecec8900)
* Connected to example.localhost (::1) port 80 (#0)
> GET / HTTP/1.1
> Host: example.localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Connection: close
< Transfer-Encoding: chunked
< 
* Closing connection 0
example

With the same server instance still running, if I send an HTTP 1.0 request afterwards, then that works too:

$ curl http://example.localhost --verbose --http1.0
* Expire in 0 ms for 6 (transfer 0x562983d02900)
…
* Expire in 1 ms for 1 (transfer 0x562983d02900)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149998 ms for 3 (transfer 0x562983d02900)
* Expire in 200 ms for 4 (transfer 0x562983d02900)
* Connected to example.localhost (::1) port 80 (#0)
> GET / HTTP/1.0
> Host: example.localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< 
* Closing connection 0
example

My tracing code created these logs from the last 2 requests:

2020-08-15T21:54:46.618460Z   INFO - prax: binding to [::]:20559
2020-08-15T21:54:46.619094Z  DEBUG - prax: beginning to handle clients
2020-08-15T21:54:49.596340Z  DEBUG - prax: spawning handler for client
2020-08-15T21:54:49.596432Z  DEBUG - prax: spawned handler for client
2020-08-15T21:54:49.596716Z   INFO - prax: starting rack application: example (port 46489)
2020-08-15T21:54:50.212432Z  DEBUG - prax: executed command "start" and received message "ok"
2020-08-15T21:54:50.212924Z  DEBUG - prax: GET /
2020-08-15T21:54:50.213093Z  DEBUG - prax: sending request from client to server
2020-08-15T21:54:50.214172Z  DEBUG - prax: done sending request from client to server
2020-08-15T21:54:50.214328Z  DEBUG - prax: returning response from server to client
2020-08-15T21:54:50.217108Z  DEBUG - prax: copying stream
2020-08-15T21:54:50.217215Z  DEBUG - prax: about to read bytes
2020-08-15T21:54:50.217309Z  DEBUG - prax: read 9 bytes
2020-08-15T21:54:50.217444Z  DEBUG - prax: wrote 9 bytes
2020-08-15T21:54:50.217551Z  DEBUG - prax: finished copying stream
2020-08-15T21:54:50.217660Z  DEBUG - prax: copying stream
2020-08-15T21:54:50.217735Z  DEBUG - prax: about to read bytes
2020-08-15T21:54:50.217856Z  DEBUG - prax: read 2 bytes
2020-08-15T21:54:50.217981Z  DEBUG - prax: wrote 2 bytes
2020-08-15T21:54:50.218065Z  DEBUG - prax: finished copying stream
2020-08-15T21:54:50.218139Z  DEBUG - prax: done returning response from server to client
2020-08-15T21:54:50.218270Z  DEBUG - prax: closing socket
2020-08-15T21:54:50.218351Z  DEBUG - prax: closed socket
2020-08-15T21:54:51.973387Z  DEBUG - prax: spawning handler for client
2020-08-15T21:54:51.973461Z  DEBUG - prax: spawned handler for client
2020-08-15T21:54:51.973740Z  DEBUG - prax: GET /
2020-08-15T21:54:51.973793Z  DEBUG - prax: sending request from client to server
2020-08-15T21:54:51.974114Z  DEBUG - prax: done sending request from client to server
2020-08-15T21:54:51.974166Z  DEBUG - prax: returning response from server to client
2020-08-15T21:54:51.982769Z  DEBUG - prax: copying stream
2020-08-15T21:54:51.982842Z  DEBUG - prax: about to read bytes
2020-08-15T21:54:51.982898Z  DEBUG - prax: read 7 bytes
2020-08-15T21:54:51.982969Z  DEBUG - prax: wrote 7 bytes
2020-08-15T21:54:51.983020Z  DEBUG - prax: about to read bytes
2020-08-15T21:54:51.983073Z  DEBUG - prax: read 0 bytes
2020-08-15T21:54:51.983123Z  DEBUG - prax: finished copying stream
2020-08-15T21:54:51.983173Z  DEBUG - prax: done returning response from server to client
2020-08-15T21:54:51.983283Z  DEBUG - prax: closing socket
2020-08-15T21:54:51.983352Z  DEBUG - prax: closed socket

However, if I restart the server, and then make an HTTP 1.0 request first, then cURL gets stuck:

$ curl http://example.localhost --verbose --http1.0
* Expire in 0 ms for 6 (transfer 0x55973702a900)
…
* Expire in 0 ms for 1 (transfer 0x55973702a900)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149999 ms for 3 (transfer 0x55973702a900)
* Expire in 200 ms for 4 (transfer 0x55973702a900)
* Connected to example.localhost (::1) port 80 (#0)
> GET / HTTP/1.0
> Host: example.localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< 
 ← Cursor is here, waiting, waiting…

Meanwhile, the tracing code produces very similar logs to the “1: 1.1, 2: 1.0” scenario:

2020-08-15T21:57:43.211112Z   INFO - prax: binding to [::]:20559
2020-08-15T21:57:43.211396Z  DEBUG - prax: beginning to handle clients
2020-08-15T21:57:48.741438Z  DEBUG - prax: spawning handler for client
2020-08-15T21:57:48.741531Z  DEBUG - prax: spawned handler for client
2020-08-15T21:57:48.741813Z   INFO - prax: starting rack application: example (port 37117)
2020-08-15T21:57:49.347365Z  DEBUG - prax: executed command "start" and received message "ok"
2020-08-15T21:57:49.347965Z  DEBUG - prax: GET /
2020-08-15T21:57:49.348216Z  DEBUG - prax: sending request from client to server
2020-08-15T21:57:49.349285Z  DEBUG - prax: done sending request from client to server
2020-08-15T21:57:49.349519Z  DEBUG - prax: returning response from server to client
2020-08-15T21:57:49.352808Z  DEBUG - prax: copying stream
2020-08-15T21:57:49.352907Z  DEBUG - prax: about to read bytes
2020-08-15T21:57:49.353001Z  DEBUG - prax: read 7 bytes
2020-08-15T21:57:49.353131Z  DEBUG - prax: wrote 7 bytes
2020-08-15T21:57:49.353222Z  DEBUG - prax: about to read bytes
2020-08-15T21:57:49.353332Z  DEBUG - prax: read 0 bytes
2020-08-15T21:57:49.353439Z  DEBUG - prax: finished copying stream
2020-08-15T21:57:49.353545Z  DEBUG - prax: done returning response from server to client
2020-08-15T21:57:49.353706Z  DEBUG - prax: closing socket
2020-08-15T21:57:49.353822Z  DEBUG - prax: closed socket

After hanging for a few minutes, I cancel the cURL request.

With the same (second) server instance still running, if I make another HTTP 1.0 request, then that one goes through:

jackson@debian:~$ curl http://example.localhost --verbose --http1.0
* Expire in 0 ms for 6 (transfer 0x564942bc1900)
…
* Expire in 1 ms for 1 (transfer 0x564942bc1900)
*   Trying ::1...
* TCP_NODELAY set
* Expire in 149998 ms for 3 (transfer 0x564942bc1900)
* Expire in 200 ms for 4 (transfer 0x564942bc1900)
* Connected to example.localhost (::1) port 80 (#0)
> GET / HTTP/1.0
> Host: example.localhost
> User-Agent: curl/7.64.0
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< 
* Closing connection 0
example

And the following is appended to the logs:

2020-08-15T22:02:31.786711Z  DEBUG - prax: spawning handler for client
2020-08-15T22:02:31.786789Z  DEBUG - prax: spawned handler for client
2020-08-15T22:02:31.787080Z  DEBUG - prax: GET /
2020-08-15T22:02:31.787136Z  DEBUG - prax: sending request from client to server
2020-08-15T22:02:31.787468Z  DEBUG - prax: done sending request from client to server
2020-08-15T22:02:31.787522Z  DEBUG - prax: returning response from server to client
2020-08-15T22:02:31.788900Z  DEBUG - prax: copying stream
2020-08-15T22:02:31.788970Z  DEBUG - prax: about to read bytes
2020-08-15T22:02:31.789026Z  DEBUG - prax: read 7 bytes
2020-08-15T22:02:31.789097Z  DEBUG - prax: wrote 7 bytes
2020-08-15T22:02:31.789150Z  DEBUG - prax: about to read bytes
2020-08-15T22:02:31.790163Z  DEBUG - prax: read 0 bytes
2020-08-15T22:02:31.790243Z  DEBUG - prax: finished copying stream
2020-08-15T22:02:31.790315Z  DEBUG - prax: done returning response from server to client
2020-08-15T22:02:31.790448Z  DEBUG - prax: closing socket
2020-08-15T22:02:31.790550Z  DEBUG - prax: closed socket

So… yeah. Pretty odd. The code in Prax sure seems to write all the bytes of the response body when the very first request is an HTTP 1.0 request. It calls socket.close at the end, which ought to flush all the buffered bytes out to the client. And yet, cURL just doesn’t receive the response body.

Say that I run rackup myself, without Prax’s help:

$ cd test/hosts/example
$ rackup --host 127.0.0.1 --port 1234
Puma starting in single mode...
* Version 4.3.0 (ruby 2.5.1-p57), codename: Mysterious Traveller
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://127.0.0.1:1234
Use Ctrl-C to stop

If I send a cURL request straight to that Rack server, it works on the first try:

$ curl http://127.0.0.1:1234 --verbose --http1.0
* Expire in 0 ms for 6 (transfer 0x5587f5ed3900)
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Expire in 200 ms for 4 (transfer 0x5587f5ed3900)
* Connected to 127.0.0.1 (127.0.0.1) port 1234 (#0)
> GET / HTTP/1.0
> Host: 127.0.0.1:1234
> User-Agent: curl/7.64.0
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< 
* Closing connection 0
example

I guess it’s not the server’s fault, seems to be Prax’s (or maybe Crystal’s). Not sure where to go with this at this point though.

[ysbaddaden]

I think this is Prax' fault. It may get confused somewhere. I assume the Rack server is properly closing the connection since we get an EOF. Maybe Prax doesn't properly closes the client socket (despite saying so), or doesn't flush for some reason?

[ysbaddaden]

Or something in the HTTP parser, in the fallback to connection: close ?