search

socketry / falcon

A high-performance web server for Ruby, supporting HTTP/1, HTTP/2 and TLS.
https://socketry.github.io/falcon/
MIT License
2.54k stars 79 forks source link

Getting a Errno::EPIPE: Broken pipe warning #216

Open travisbell opened 5 months ago

travisbell commented 5 months ago

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 commented 5 months ago

What client are you using? wrk?

travisbell commented 5 months ago

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 commented 5 months ago

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

travisbell commented 5 months ago

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 commented 5 months ago

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

travisbell commented 5 months ago

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

ioquatix commented 5 months ago

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

ioquatix commented 5 months ago

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

ioquatix commented 5 months ago

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

travisbell commented 5 months ago

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 commented 5 months ago

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.