lowlevel_error_handler is unexpectedly invoked when an HTTP/1.1 client closes its connection first

[cjlarose]

Describe the bug

If a client opens a TCP connection, writes a HTTP/1.1 request (without explicitly specifying a Connection: close header or anything like that), reads the response, then closes the TCP connection, then puma unexpectedly invokes the lowlevel_error_handler. I think this is a regression introduced in 5.0.1, possibly by #2384.

Puma config:

port ENV['PORT'] if ENV['PORT']

app do |env|
  [200, {}, ["Hello World"]]
end

lowlevel_error_handler do |err|
  STDERR.puts err
  STDERR.puts err.backtrace
  [500, {}, ["error page"]]
end

bundle exec ruby -Ilib bin/puma -C test/config/lowlevel_test.rb

To Reproduce

$ curl -vvv http://localhost:9292
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 9292 (#0)
> GET / HTTP/1.1
> Host: localhost:9292
> User-Agent: curl/7.64.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Length: 11
<
* Connection #0 to host localhost left intact
Hello World* Closing connection 0

Expected behavior

The lowlevel handler isn't invoked, consistent with the behavior of puma v5.0.0

Desktop (please complete the following information):

• OS: macOS, Linux
• Puma Version 5.0.2

[cjlarose]

The error reported to the lowlevel_error_handler

EOFError
/Users/chris.larose/dev/puma/lib/puma/client.rb:170:in `try_to_finish'
/Users/chris.larose/dev/puma/lib/puma/reactor.rb:224:in `block in run_internal'
/Users/chris.larose/dev/puma/lib/puma/reactor.rb:157:in `each'
/Users/chris.larose/dev/puma/lib/puma/reactor.rb:157:in `run_internal'
/Users/chris.larose/dev/puma/lib/puma/reactor.rb:307:in `block in run_in_thread'

[cjlarose]

@schneems I think the problem is that the Puma::Reactor used to rely on getting ConnectionError in this case when calling Puma::Client#try_to_finish, but now it gets an EOFError instead and doesn't explicitly handle that error.

I tried to write a test to reproduce the behavior (without just calling curl), but I wasn't able to quickly. It's kinda sensitive to timing it seems, even though it's easy to reproduce with curl.

[nateberkopec]

Just thinking aloud for a moment - we don't want to report this to lowlevel_error_handler because we're saying this the client's fault, and lowlevel_error_handler is only for exceptional circumstances where Puma fumbles?

[MSP-Greg]

@cjlarose

I've got this issue showing up in a way that we can use in test.

But, if you add log_requests to your Puma config, do you see two requests shown? I'm seeing that locally, and that is odd. Also, I'm using TCPSocket, not net/http, so why two requests are logged...

[cjlarose]

Just thinking aloud for a moment - we don't want to report this to lowlevel_error_handler because we're saying this the client's fault, and lowlevel_error_handler is only for exceptional circumstances where Puma fumbles?

Yeah, I think it's a good idea to take a step back and make sure we're intentional about implementing the behavior we want instead of just blindly making puma do what it did before.

I think you are basically right in this case--though I wouldn't really assign blame to the client since I think the behavior isn't really a violation of the spec. RFC 7230 describes the behavior of HTTP connection persistence

If the "close" connection option is present, the connection will not persist after the current response; else,
If the received protocol is HTTP/1.1 (or later), the connection will persist after the current response; else,
[...]

So since curl didn't send Connection: close in the request headers, we'd expect the connection to persist, but later on,

Connections can be closed at any time, with or without intention. Implementations ought to anticipate the need to recover from asynchronous close events.

So I think curl is still fine here in its choice to close the connection.

With regard to whether or not lowlevel_error_handler should be invoked, I think in this case since the client behaved as expected by the spec and even got the response they requested successfully, it's not useful to invoke it.

lowlevel_error_handler is only for exceptional circumstances where Puma fumbles?

There are some places where the lowlevel_error_handler is invoked, but it's not Puma's fault. One example is for malformed HTTP 1.1 requests. I think even in some cases where it wasn't Puma's fault, it's good to report those errors so users can decide on their own whether or not it's something they want to be notified about. But in this case, I can't imagine anyone wanting to be notified about a client-initiated connection close.

[cjlarose]

@MSP-Greg

But, if you add log_requests to your Puma config, do you see two requests shown? I'm seeing that locally, and that is odd. Also, I'm using TCPSocket, not net/http, so why two requests are logged...

Nope. If I add log_requests to the Puma config and re-do my curl test, I only see one log message for each request.

[nateberkopec]

I think in this case since the client behaved as expected by the spec and even got the response they requested successfully, it's not useful to invoke it.

Perfect. That makes sense to me, I agree this is a regression.

[MSP-Greg]

I copied some methods from the test suite, when I bypassed those, I only had one request logged. Sorry. Got to figure out what did that...

Anyway, the following might be a fix:

 lib/puma/reactor.rb | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb
index 2941bea0e..bbc40ee49 100644
--- a/lib/puma/reactor.rb
+++ b/lib/puma/reactor.rb
@@ -254,9 +254,10 @@ def run_internal
 
                 @events.parse_error e, c
               rescue StandardError => e
-                @server.lowlevel_error(e, c.env)
-
-                c.write_error(500)
+                unless EOFError === e # assume client closed connection
+                  @server.lowlevel_error(e, c.env)
+                  c.write_error(500)
+                end
                 c.close
 
                 clear_monitor mon

or master...MSP-Greg:client-close

[cjlarose]

That would work, but the comment up above with ConnectionError nicely describes what we're doing already.

diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb
index 2941bea0..b1341358 100644
--- a/lib/puma/reactor.rb
+++ b/lib/puma/reactor.rb
@@ -229,7 +229,7 @@ module Puma
               # Don't report these to the lowlevel_error handler, otherwise
               # will be flooding them with errors when persistent connections
               # are closed.
-              rescue ConnectionError
+              rescue EOFError, ConnectionError
                 c.write_error(500)
                 c.close
 

[MSP-Greg]

Duh. LGTM. One thing though, EOFError means it's closed, but write_error is rescued...

[cjlarose]

Oh yeah that's interesting. You'd think that if we got a EOFError, then we shouldn't be able to write to the socket.

But inside Puma::Client#write_error, the write @io << ERROR_RESPONSE[status_code] succeeds and inside Puma::Client#close, the close @io.close also completes without an exception.

The Reactor relied on this same behavior before #2384, but it is weird that any of it worked at all.

I guess maybe EOFError just means that there's nothing left to read from the client socket, not necessarily that the socket is closed.

[MSP-Greg]

Along with watching the wonderful debate, I worked some more with this, and hitting Puma with a browser also logged errors. Not good. I'll work on a test tomorrow, but the fix works...

[nateberkopec]

Slapping important on this so we can fix it before the next release

[wjordan]

Pretty sure this issue has been resolved by #2279 (which refactored the error-reporting behavior into Server#client_error). The steps in #2390 (comment) no longer produce any backtrace since that PR was merged.

[MSP-Greg]

Confirmed that @wjordan is correct. I've got a test I can add, fails with 5.0.2, passes with master.

[cjlarose]

Fixed by #2279. We should of course add a test like the one in #2429 to prevent the regression in the future, but we can close this issue now since it's already fixed in master.