Connection error detected during read

[mwpastore]

I've got a bit of a head-scratcher and could use some help gathering more diagnostic information. Every so often my Puma server will send this trace over to Rollbar (courtesy of lowlevel_error_handler):

Errno::ECONNRESET: Connection reset by peer
File "<internal:prelude>" line 76 in __read_nonblock
File "<internal:prelude>" line 76 in read_nonblock
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/client.rb" line 166 in try_to_finish
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 73 in block in run_internal
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 42 in each
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 42 in run_internal
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 144 in block in run_in_thread
Puma::ConnectionError: Connection error detected during read
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/client.rb" line 170 in rescue in try_to_finish
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/client.rb" line 165 in try_to_finish
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 73 in block in run_internal
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 42 in each
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 42 in run_internal
File "/srv/rack/example.com/repo/vendor/bundle/ruby/2.3.0/gems/puma-3.4.0/lib/puma/reactor.rb" line 144 in block in run_in_thread

The funny thing is that these errors don't appear to be related to any requests. This Puma instance sits behind HAproxy and there are no requests in the Puma log or the HAproxy log that correspond to the times the errors occur. I added pp env to the lowlevel_error_handler (side note: I can't send env to Rollbar; it triggers a "can't modify frozen Array" error) and here's what it looks like:

{"rack.version"=>[1, 3],
 "rack.errors"=>#<IO:<STDERR>>,
 "rack.multithread"=>true,
 "rack.multiprocess"=>false,
 "rack.run_once"=>false,
 "SCRIPT_NAME"=>"",
 "QUERY_STRING"=>"",
 "SERVER_PROTOCOL"=>"HTTP/1.1",
 "SERVER_SOFTWARE"=>"puma 3.4.0 Owl Bowl Brawl",
 "GATEWAY_INTERFACE"=>"CGI/1.2"}

What's the best way to go about gathering some additional information to see what's happening here, and what Puma's trying to do when it happens? Thanks in advance.

[dentarg]

We also noticed this in an application running on Heroku (the exception information was sent over to Sentry). We upgrade the application from Puma 2.16.0 to 3.4.0 today. Have only seen it once though, and I have no repro for it. If it continues to be a problem I will report back here.

EOFError: end of file reached
  from puma/client.rb:166:in `read_nonblock'
  from puma/client.rb:166:in `try_to_finish'
  from puma/reactor.rb:73:in `block in run_internal'
  from puma/reactor.rb:42:in `each'
  from puma/reactor.rb:42:in `run_internal'
  from puma/reactor.rb:144:in `block in run_in_thread'
Puma::ConnectionError: Connection error detected during read
  from puma/client.rb:170:in `rescue in try_to_finish'
  from puma/client.rb:165:in `try_to_finish'
  from puma/reactor.rb:73:in `block in run_internal'
  from puma/reactor.rb:42:in `each'
  from puma/reactor.rb:42:in `run_internal'
  from puma/reactor.rb:144:in `block in run_in_thread'

[dentarg]

We continue to see Puma::ConnectionError: Connection error detected during read errors.

[subakva]

We also started seeing the same errors ("Puma::ConnectionError: Connection error detected during read") on Heroku when we upgraded to 3.4. The release notes say that version includes #894 to trigger the lowlevel_error_handler block more often.

I assume this was happening quietly all along, and I think it's part of normal operation in that environment. If that's the case, I'd be interested in any advice on sorting the expected errors from the unexpected errors so that I can filter the noise out of our error notifications without potentially hiding real issues.

I'd also be interested to hear if I'm totally wrong about this being "normal" in a Heroku legacy 1x dyno.

[evanphx]

This is mostly likely related to keep-alive connections. HAProxy is perhaps terminating the connection. The reason they're showing up now is a recent change to send errors that occur within the reactor to the lowelevel_handler. I'm going to make a change to that code to ignore any IO errors, so these should go away.

[mwpastore]

@evanphx Ah, I thought I tried disabling keepalive in my HAproxy backend to work around this "issue", but I only disabled TCP keepalive, not HTTP keepalive mode. I added "option http-server-close" just for kicks; I'll let you know if Puma continues throwing this error even so. Thank you!

[mwpastore]

Sure enough, no errors since making the HAproxy configuration change, so keepalives are definitely to blame here.

[dentarg]

@evanphx any plans in the near future on making a new release with the fix here?

[kapso]

Just upgraded to 5.0 and seeing this error on Heroku as well

2020-09-23T21:36:23.707626+00:00 app[web.1]: 2020-09-23 21:36:23 +0000 HTTP connection error: #<Puma::ConnectionError: Connection error detected during read>
2020-09-23T21:38:30.827635+00:00 app[web.1]: 2020-09-23 21:38:30 +0000 HTTP connection error: #<Puma::ConnectionError: Connection error detected during read>

[nateberkopec]

Oh, that's actually helpful. I'm locking this issue now because it's old/solved, but thanks @kapso for pointing out the original reason why we hid these errors!

Please move all discussion for the 5.0 version of this issue to #2371