puma: lowlevel_error_handler is unexpectedly invoked when an HTTP/1.1 client closes its connection first
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
About this issue
- Original URL
- State: closed
- Created 4 years ago
- Reactions: 1
- Comments: 16 (16 by maintainers)
Commits related to this issue
- Add test_client_quick_close_no_lowlevel_error_handler_call See https://github.com/puma/puma/issues/2390 Fixed by https://github.com/puma/puma/pull/2279 Fails in 5.0.2 — committed to MSP-Greg/puma by MSP-Greg 4 years ago
- Add test_client_quick_close_no_lowlevel_error_handler_call See https://github.com/puma/puma/issues/2390 Fixed by https://github.com/puma/puma/pull/2279 Fails in 5.0.2 — committed to MSP-Greg/puma by MSP-Greg 4 years ago
- Add test_client_quick_close_no_lowlevel_error_handler_call See https://github.com/puma/puma/issues/2390 Fixed by https://github.com/puma/puma/pull/2279 Fails in 5.0.2 — committed to MSP-Greg/puma by MSP-Greg 4 years ago
- Add test_client_quick_close_no_lowlevel_error_handler_call (#2429) See https://github.com/puma/puma/issues/2390 Fixed by https://github.com/puma/puma/pull/2279 Fails in 5.0.2 — committed to puma/puma by MSP-Greg 4 years ago
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
So since
curldidn’t sendConnection: closein the request headers, we’d expect the connection to persist, but later on,So I think
curlis still fine here in its choice to close the connection.With regard to whether or not
lowlevel_error_handlershould 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.There are some places where the
lowlevel_error_handleris 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.Confirmed that @wjordan is correct. I’ve got a test I can add, fails with 5.0.2, passes with master.
Pretty sure this issue has been resolved by #2279 (which refactored the error-reporting behavior into
Server#client_error). The steps in https://github.com/puma/puma/issues/2390#issue-710749084 no longer produce any backtrace since that PR was merged.Slapping
importanton this so we can fix it before the next releaseAlong 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…
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 insidePuma::Client#close, the close@io.closealso 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
EOFErrorjust means that there’s nothing left to read from the client socket, not necessarily that the socket is closed.Duh. LGTM. One thing though, EOFError means it’s closed, but
write_erroris rescued…