async-http icon indicating copy to clipboard operation
async-http copied to clipboard

Race conditions in tests

Open ioquatix opened this issue 5 months ago • 0 comments

> bundle exec sus test/async/http/proxy.rb
 0.26s     warn: Async::HTTP::Client: running example [oid=0x7a0] [ec=0x7a8] [pid=1270945] [2025-07-14 18:51:55 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP10 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
 0.77s     warn: Async::HTTP::Client: running example [oid=0x7e8] [ec=0x7f0] [pid=1270945] [2025-07-14 18:51:56 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP10 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
 1.21s     warn: Async::HTTP::Client: running example [oid=0x830] [ec=0x838] [pid=1270945] [2025-07-14 18:51:56 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP10 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
 1.53s     warn: Async::HTTP::Client: running example [oid=0x920] [ec=0x928] [pid=1270945] [2025-07-14 18:51:57 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP11 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
 2.01s     warn: Async::HTTP::Client: running example [oid=0x968] [ec=0x970] [pid=1270945] [2025-07-14 18:51:57 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP11 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
 2.49s     warn: Async::HTTP::Client: running example [oid=0x9b0] [ec=0x9b8] [pid=1270945] [2025-07-14 18:51:58 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP11 pool to drain: #<Async::Pool::Controller(1/∞) 1/1*/1>
  2.8s     warn: Async::HTTP::Client: running example [oid=0xaa0] [ec=0xaa8] [pid=1270945] [2025-07-14 18:51:58 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP2 pool to drain: #<Async::Pool::Controller(1/∞) 1/128/>
 3.28s     warn: Async::HTTP::Client: running example [oid=0xae8] [ec=0xaf0] [pid=1270945] [2025-07-14 18:51:58 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP2 pool to drain: #<Async::Pool::Controller(1/∞) 1/128/>
 3.77s     warn: Async::HTTP::Client: running example [oid=0xb30] [ec=0xb38] [pid=1270945] [2025-07-14 18:51:59 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP2 pool to drain: #<Async::Pool::Controller(1/∞) 1/128/>
 3.77s     warn: Async::Task: Writing #<Protocol::HTTP::Body::Writable:0x00007f40a897dc00> to #<Async::HTTP::Protocol::HTTP2::Response::Stream:0x00007f409ee17bd0>. [oid=0xb40] [ec=0xb48] [pid=1270945] [2025-07-14 18:51:59 +1200]
               | Task may have ended with unhandled exception.
               |   Errno::ECONNRESET: Connection reset by peer
               |   → /home/samuel/.rubies/ruby-3.4.4/lib/ruby/3.4.0/socket.rb:457 in 'BasicSocket#__read_nonblock'
               |     /home/samuel/.rubies/ruby-3.4.4/lib/ruby/3.4.0/socket.rb:457 in 'BasicSocket#read_nonblock'
               |     /home/samuel/.gem/ruby/3.4.4/gems/io-stream-0.10.0/lib/io/stream/buffered.rb:142 in 'IO::Stream::Buffered#sysread'
               |     /home/samuel/.gem/ruby/3.4.4/gems/io-stream-0.10.0/lib/io/stream/readable.rb:347 in 'IO::Stream::Readable#fill_read_buffer'
               |     /home/samuel/.gem/ruby/3.4.4/gems/io-stream-0.10.0/lib/io/stream/readable.rb:118 in 'IO::Stream::Readable#read_partial'
               |     lib/async/http/body/pipe.rb:82 in 'Async::HTTP::Body::Pipe#writer'
               |     /home/samuel/.gem/ruby/3.4.4/gems/async-2.25.0/lib/async/task.rb:201 in 'block in Async::Task#run'
               |     /home/samuel/.gem/ruby/3.4.4/gems/async-2.25.0/lib/async/task.rb:439 in 'block in Async::Task#schedule'
 3.77s     warn: Async::Task: Upstream writer. [oid=0xb50] [ec=0xb58] [pid=1270945] [2025-07-14 18:51:59 +1200]
               | Task may have ended with unhandled exception.
               |   Protocol::HTTP2::StreamError: Stream closed!
               |   → /home/samuel/.gem/ruby/3.4.4/gems/protocol-http-0.51.0/lib/protocol/http/body/writable.rb:68 in 'Protocol::HTTP::Body::Writable#read'
               |     lib/async/http/protocol/http2/input.rb:22 in 'Async::HTTP::Protocol::HTTP2::Input#read'
               |     /home/samuel/.gem/ruby/3.4.4/gems/protocol-http-0.51.0/lib/protocol/http/body/stream.rb:402 in 'Protocol::HTTP::Body::Stream#read_next'
               |     /home/samuel/.gem/ruby/3.4.4/gems/protocol-http-0.51.0/lib/protocol/http/body/stream.rb:110 in 'Protocol::HTTP::Body::Stream::Reader#read_partial'
               |     test/async/http/proxy.rb:152 in 'block (7 levels) in <top (required)>'
               |     /home/samuel/.gem/ruby/3.4.4/gems/async-2.25.0/lib/async/task.rb:201 in 'block in Async::Task#run'
               |     /home/samuel/.gem/ruby/3.4.4/gems/async-2.25.0/lib/async/task.rb:439 in 'block in Async::Task#schedule'
 3.78s     warn: Async::HTTP::Client: running example [oid=0xb78] [ec=0xb80] [pid=1270945] [2025-07-14 18:51:59 +1200]
               | Waiting for Async::HTTP::Protocol::HTTP2 pool to drain: #<Async::Pool::Controller(1/∞) 1/128/>
27 passed out of 27 total (75 assertions)
🏁 Finished in 3.8s; 19.853 assertions per second.
🐢 Slow tests:
	487.8ms: describe Async::HTTP::Protocol::HTTP10 it behaves like a proxy with proxied client with authorization header required with request includes headers it succeeds test/async/http/proxy.rb:240:209
	484.1ms: describe Async::HTTP::Protocol::HTTP2 it behaves like a proxy with proxied client it can get secure website test/async/http/proxy.rb:248:189
	481.2ms: describe Async::HTTP::Protocol::HTTP11 it behaves like a proxy with proxied client it can get secure website test/async/http/proxy.rb:244:189
	479.6ms: describe Async::HTTP::Protocol::HTTP11 it behaves like a proxy with proxied client with authorization header required with request includes headers it succeeds test/async/http/proxy.rb:244:209
	460.0ms: describe Async::HTTP::Protocol::HTTP10 it behaves like a proxy with proxied client it can get secure website test/async/http/proxy.rb:240:189
	452.0ms: describe Async::HTTP::Protocol::HTTP2 it behaves like a proxy with proxied client with authorization header required with request includes headers it succeeds test/async/http/proxy.rb:248:209
	315.7ms: describe Async::HTTP::Protocol::HTTP11 it behaves like a proxy with proxied client it can get insecure website test/async/http/proxy.rb:244:172
	302.2ms: describe Async::HTTP::Protocol::HTTP10 it behaves like a proxy with proxied client it can get insecure website test/async/http/proxy.rb:240:172
	296.9ms: describe Async::HTTP::Protocol::HTTP2 it behaves like a proxy with proxied client it can get insecure website test/async/http/proxy.rb:248:172

In some situations it looks like there is race during the connection shutdown.

ioquatix avatar Jul 14 '25 07:07 ioquatix