Getting a Errno::EPIPE: Broken pipe warning

[travisbell]

Hey Samuel,

I was giving one of our apps a spin in Falcon on Ruby 3.3 and am randomly getting this warning/error after a request:

 1m     warn: Async::Task: Reading HTTP/1.1 requests for Async::HTTP::Protocol::HTTP1::Server. [oid=0x846c] [ec=0x8480] [pid=3684] [2024-01-10 18:24:09 +0000]
               | Task may have ended with unhandled exception.
               |   Errno::EPIPE: Broken pipe
               |   → /usr/local/lib/ruby/3.3.0/socket.rb:461 in `__write_nonblock'
               |     /usr/local/lib/ruby/3.3.0/socket.rb:461 in `write_nonblock'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:200 in `async_send'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:46 in `block in wrap_blocking_method'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:140 in `write'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/stream.rb:158 in `block in flush'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/semaphore.rb:87 in `acquire'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/stream.rb:153 in `flush'
               |     /usr/local/bundle/gems/protocol-http1-0.16.1/lib/protocol/http1/connection.rb:354 in `write_chunked_body'
               |     /usr/local/bundle/gems/protocol-http1-0.16.1/lib/protocol/http1/connection.rb:400 in `write_body'
               |     /usr/local/bundle/gems/async-http-0.61.0/lib/async/http/protocol/http1/server.rb:89 in `each'
               |     /usr/local/bundle/gems/async-http-0.61.0/lib/async/http/server.rb:40 in `accept'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/server.rb:15 in `block in accept_each'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/socket.rb:58 in `block in accept'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/task.rb:161 in `block in run'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/task.rb:331 in `block in schedule'

I am starting Falon with the following command:

bundle exec falcon -n 1 -b http://0.0.0.0 -p 8081 -c config.ru

This is on Ubuntu 20.04 by the way.

I can't seem to really figure out what's causing it. Any hints or tips?

[ioquatix]

What client are you using? wrk?

[travisbell]

This was actually just clicking through the app in Firefox/Safari. Every few page loads, after the page would load I’d see that warning thrown.

Can’t say it seemed to really affect anything. Is it something to do with connections not being cleanly closed?

[ioquatix]

Can you run Falcon with --verbose to capture more logs?

[travisbell]

No problem, here's the dump for a request that spits it back:

22.12s     info: Async::HTTP::Protocol::HTTP1::Request: GET /remote/panel?panel=trailer_scroller&group=popular from #<Addrinfo: 172.18.0.1:39586 TCP> [oid=0x6acc] [ec=0x67e8] [pid=135202] [2024-01-11 15:40:44 +0000]
               | Responding with: 200 {"link"=>["</assets/2/source-sans-pro-v14-vietnamese_latin-ext_latin_greek-ext_greek_cyrillic-ext_cyrillic-regular.woff2>; rel=preload; as=font; type=font/woff2; crossorigin"], "content-type"=>"text/html;charset=utf-8", "cache-control"=>["no-store", "must-revalidate", "private", "max-age=0"], "x-miniprofiler-ids"=>["xdugjxcaf3v9bu3jtn48", "jwh36ajka7w3oz81z1lv"], "set-cookie"=>["__profilin=p%3Dt; path=/; HttpOnly; SameSite=Lax", "tmdb.session=AXlA5K62fBZbvGzoLyeEixyLQ1327mS5gymn_X26emDGq57jtAvzeqJ1hAK_BhOOPfYYIVsWPI1eO36Su1x0_mGLCwVNYpG3qPH4wlwXYq-pH8jriTgOXQ2NC7HhXL_Y8ees3QBHEZQfjKfxudVoag-CRQfXJUeiz3QmUc0X-TP7RoNWGwAujVelyPMywsMytzFkQXyXzfUHmlispoIVfIfnVD0arFhL-5mf3rC9eoqCqpEPxgYeq8OSSYwwDNblUyaWHMGnyMpxSdW241-_n7iYTdsp3n8JZ7xFKcZ_PUdTUIrli8Y-R5TPeFPBqRoOIcrx6uvPBLhNqu3FTeMPIV1jh1UbwGqvXFAR3GbQ2wUcESWfQgIAW9o585-J4Bn3HfnAFZ7djsn1R1NB6pEogK0y8JHXbYoeoud_aPCitHQuY8Cl1av8dAFwOj-_Gffm6nXg8xGyjPr4EGMocKJ5UtH10DoEECbFS1Ga5trPyj92oU4BxrmJ043KsN3Ldl8kmCDLW_mW-SSKECdIPybDRdLyJeuoh4oWJ4FzzSveGJa7eRs48d_To9bCIdUVx1TC5wxOX37zYebZDUQ4DBD2C4x7nyyb_yMvtYY2ml5rYmhAcEDPQjZ_MEe6DLB73fcpXdgZFiHk2SlEgyGa2lGmYEFv7t6QyeTHXqCdlWVqCvh4Ny5tbnabPonYTbEFHLoVmg%3D%3D; path=/; max-age=604800; HttpOnly; SameSite=Lax"], "content-language"=>["en-CA"], "strict-transport-security"=>["max-age=31536000; includeSubDomains; preload"], "x-xss-protection"=>["1; mode=block"], "x-content-type-options"=>["nosniff"], "etag"=>"W/\"657f8cdc33740dc4bef90a5aae147e61\"", "vary"=>["accept-encoding"], "content-encoding"=>["gzip"]}; #<Protocol::Rack::Body::Enumerable length=nil body=NilClass> | #<Async::HTTP::Body::Statistics sent 167 bytes; took 2.8s in total; took 2.7s until first chunk>
22.12s    error: Async::HTTP::Protocol::HTTP1::Request: GET /remote/panel?panel=trailer_scroller&group=popular from #<Addrinfo: 172.18.0.1:39586 TCP> [oid=0x6acc] [ec=0x67e8] [pid=135202] [2024-01-11 15:40:44 +0000]
               | Errno::EPIPE: Broken pipe
22.12s     warn: Async::Task: GET /remote/panel?panel=trailer_scroller&group=popular from #<Addrinfo: 172.18.0.1:39586 TCP> [oid=0x6e00] [ec=0x67e8] [pid=135202] [2024-01-11 15:40:44 +0000]
               | Task may have ended with unhandled exception.
               |   Errno::EPIPE: Broken pipe
               |   → /usr/local/lib/ruby/3.3.0/socket.rb:461 in `__write_nonblock'
               |     /usr/local/lib/ruby/3.3.0/socket.rb:461 in `write_nonblock'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:200 in `async_send'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:46 in `block in wrap_blocking_method'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/generic.rb:140 in `write'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/stream.rb:158 in `block in flush'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/semaphore.rb:87 in `acquire'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/stream.rb:153 in `flush'
               |     /usr/local/bundle/gems/protocol-http1-0.16.1/lib/protocol/http1/connection.rb:354 in `write_chunked_body'
               |     /usr/local/bundle/gems/protocol-http1-0.16.1/lib/protocol/http1/connection.rb:400 in `write_body'
               |     /usr/local/bundle/gems/async-http-0.61.0/lib/async/http/protocol/http1/server.rb:89 in `each'
               |     /usr/local/bundle/gems/async-http-0.61.0/lib/async/http/server.rb:40 in `accept'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/server.rb:15 in `block in accept_each'
               |     /usr/local/bundle/gems/async-io-1.38.1/lib/async/io/socket.rb:58 in `block in accept'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/task.rb:161 in `block in run'
               |     /usr/local/bundle/gems/async-2.8.0/lib/async/task.rb:331 in `block in schedule'
               |     /usr/local/bundle/gems/newrelic_rpm-9.7.0/lib/new_relic/agent/tracer.rb:434 in `block (2 levels) in thread_block_with_current_transaction'
               |     /usr/local/bundle/gems/newrelic_rpm-9.7.0/lib/new_relic/agent/tracer.rb:357 in `capture_segment_error'
               |     /usr/local/bundle/gems/newrelic_rpm-9.7.0/lib/new_relic/agent/tracer.rb:433 in `block in thread_block_with_current_transaction'

[ioquatix]

And just to confirm, you've seen this behaviour in both Firefox and Safari?

[travisbell]

Yup, and I just tried Chrome for some extra sanity and can reproduce it there too.

[ioquatix]

The Enumerable body with NilClass looks a bit odd to me, let me check it.

[ioquatix]

Oh, do you also see the failed requests in the web inspector of the respective browsers? Can you share some screenshots if visible?

[ioquatix]

Is there any chance you can share the app source code with me so I can run it locally to debug?

[travisbell]

I can't share this app, but I'll spend a few minutes this week trying to pair this down to a reproducible example.

[ioquatix]

Browsers do have a habit of closing connections ad-hoc if they don't need the response. HTTP/1 doesn't have a good mechanism for "I don't need the response." except closing the connection. It's possible once it gets the response headers with the etag, it doesn't need the response body and closes the connection. It might be to do with the cache headers you are replying with.