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

Improve test consistency

Open ioquatix opened this issue 10 months ago • 4 comments

Some tests are logging connection errors (usually ones testing error handling):

> bundle exec sus test/async/http/retry.rb:36
  0.1s     warn: Async::Task: Reading HTTP/1.1 requests for Async::HTTP::Protocol::HTTP1::Server. [oid=0x4d8] [ec=0x4e0] [pid=77118] [2025-03-12 17:23:34 +1300]
               | Task may have ended with unhandled exception.
               |   Errno::ECONNRESET: Connection reset by peer
               |   → <internal:io> 63:in 'IO#read_nonblock'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/io-stream-0.6.1/lib/io/stream/buffered.rb:114 in 'IO::Stream::Buffered#sysread'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/io-stream-0.6.1/lib/io/stream/generic.rb:327 in 'IO::Stream::Generic#fill_read_buffer'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/io-stream-0.6.1/lib/io/stream/generic.rb:164 in 'IO::Stream::Generic#gets'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/protocol-http1-0.30.0/lib/protocol/http1/connection.rb:289 in 'Protocol::HTTP1::Connection#read_line?'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/protocol-http1-0.30.0/lib/protocol/http1/connection.rb:304 in 'Protocol::HTTP1::Connection#read_request_line'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/protocol-http1-0.30.0/lib/protocol/http1/connection.rb:318 in 'Protocol::HTTP1::Connection#read_request'
               |     lib/async/http/protocol/http1/request.rb:26 in 'Async::HTTP::Protocol::HTTP1::Request.read'
               |     lib/async/http/protocol/http1/server.rb:48 in 'Async::HTTP::Protocol::HTTP1::Server#next_request'
               |     lib/async/http/protocol/http1/server.rb:65 in 'Async::HTTP::Protocol::HTTP1::Server#each'
               |     lib/async/http/server.rb:50 in 'Async::HTTP::Server#accept'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/io-endpoint-0.15.2/lib/io/endpoint/wrapper.rb:216 in 'block (2 levels) in IO::Endpoint::Wrapper#accept'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/async-2.23.1/lib/async/task.rb:200 in 'block in Async::Task#run'
               |     /Users/samuel/.gem/ruby/3.4.2/gems/async-2.23.1/lib/async/task.rb:438 in 'block in Async::Task#schedule'
1 passed out of 1 total (1 assertions)
🏁 Finished in 155.3ms; 6.44 assertions per second.
🐢 Slow tests:
  155.2ms: describe consistent retry behaviour it retries with empty body test/async/http/retry.rb:36

But not all the time. I think we should correctly capture expected logs so that unexpected error logs can be identified.

ioquatix avatar Mar 12 '25 04:03 ioquatix

It not only happens in the tests, I have encountered into this problem in almost 100% reproduction rate.

In my scenario, I have a service of bin/vite dev for producing frontend stuffs in development mode, see:

# falcon.rb

# !/usr/bin/env -S falcon host

require "falcon/environment/rack"
require "falcon/environment/supervisor"

port = ENV["PORT"] || 4000

service 'supervisor' do
  include Falcon::Environment::Supervisor
end

service 'lattice-editor' do
  include Falcon::Environment::Rack

  endpoint Async::HTTP::Endpoint.parse("http://0.0.0.0:#{port}").with(protocol: Async::HTTP::Protocol::HTTP)
end


require_relative "config/environment"

if Rails.env.development?
  # Start the service of bin/vite
  service 'vite' do
    include Vite::Environment
  end
end

There would be a huge number of resources to be fetched during loading in development mode (since it hasn't been built and packed yet):

Image

Some of the resources (1-5%) would trigger such behavior randomly, which is interesting. It happens a LOT more frequently if most of the resources are cached (with a 304 response), maybe because it is more frequent somehow. I might provide more logs once I investigate it deeper.

Image

From wireshark, it looks like the server reset the TCP connection after the SYN randomly.

dsh0416 avatar Apr 17 '25 13:04 dsh0416

probably linked with https://github.com/socketry/falcon/issues/254

dsh0416 avatar Apr 17 '25 14:04 dsh0416

Thanks for the detailed bug report. Are you able to create a git repo with the reproduction so I can run it easily?

ioquatix avatar Apr 17 '25 14:04 ioquatix

I tried to reproduce it with sinatra + lots of static files but failed. My use case combines rails + inertia + vite_ruby + vue.js and lots of js libraries, which is a little bit hard to create a minimal reproduction. I'll be still working on that.

UPDATE: I got little bit confused that it looks like when using kqueue and select on macos, this would happen a lot more often than a linux server...

dsh0416 avatar Apr 17 '25 15:04 dsh0416