From f282c22d34298f4c421a6f70593d5445b1dbfd6b Mon Sep 17 00:00:00 2001 From: Richard Schneeman Date: Sun, 27 Sep 2020 11:29:28 -0500 Subject: [PATCH] [close #2371] Do not log EOFError (#2384) * Failing test for #2371 The EOF can be triggered by opening a connection, not writing to it, then closing the connection. When this happens we can detect if an error was logged or not by inspecting the stderr string. This test fails * [close #2371] Do not log EOFError This is a continuation from #2382. One of the ways that an EOFError can be triggered is by opening a connection, not writing to it, then closing it (there may be others). This should be an expected and non-exceptional activity. When it happens we should not log it. This commit gets the test in the prior commit to pass. The change to client.rb makes sense to me as this is the initial place where we're reading from the socket and then finding out the stream has been closed. Im not quite sure why the code in server.rb is needed. I think this comes from when the server is shutting down and trying to finish out connections. I don't think this is the 100% right way to do things. I'm guessing that if we get an EOFError on a connection we should somehow consider it "dead" and never try to read from it again. I don't know if there's a better way to signify this in the `try_to_finish` method of client.rb --- History.md | 1 + lib/puma/client.rb | 4 +++- lib/puma/server.rb | 6 +++++- test/test_puma_server.rb | 11 +++++++++++ 4 files changed, 20 insertions(+), 2 deletions(-) diff --git a/History.md b/History.md index 556df6bd0a..af2bf32210 100644 --- a/History.md +++ b/History.md @@ -9,6 +9,7 @@ * Prevent connections from entering Reactor after shutdown begins ([#2377]) * Fix error backtrace debug logging && Do not log request dump if it is not parsed ([#2376]) * Split TCP_CORK and TCP_INFO ([#2372]) + * Do not log EOFError when a client connection is closed without write (#2384) * Refactor * Change Events#ssl_error signature from (error, peeraddr, peercert) to (error, ssl_socket) ([#2375]) diff --git a/lib/puma/client.rb b/lib/puma/client.rb index 4289f592c8..f4f075b85d 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -157,7 +157,9 @@ def try_to_finish data = @io.read_nonblock(CHUNK_SIZE) rescue IO::WaitReadable return false - rescue SystemCallError, IOError, EOFError + rescue EOFError + # Swallow error, don't log + rescue SystemCallError, IOError raise ConnectionError, "Connection error detected during read" end diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 804011e3ca..a6095c49e5 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -246,7 +246,11 @@ def run(background=true) client.close @events.parse_error e, client - rescue ConnectionError, EOFError, ThreadPool::ForceShutdown => e + rescue EOFError => e + client.close + + # Swallow, do not log + rescue ConnectionError, ThreadPool::ForceShutdown => e client.close @events.connection_error e, client diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 0953d6deb1..58faf2440e 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -256,6 +256,17 @@ def test_doesnt_print_backtrace_in_production assert_match(/HTTP\/1.0 500 Internal Server Error/, data) end + + def test_eof_on_connection_close_is_not_logged_as_an_error + server_run + + new_connection.close # Make a connection and close without writing + + @server.stop(true) + stderr = @events.stderr.string + assert stderr.empty?, "Expected stderr from server to be empty but it was #{stderr.inspect}" + end + def test_force_shutdown_custom_error_message handler = lambda {|err, env, status| [500, {"Content-Type" => "application/json"}, ["{}\n"]]} @server = Puma::Server.new @app, @events, {:lowlevel_error_handler => handler, :force_shutdown_after => 2}