Odd `Timeout` behaviour in async context

[agalloch]

Hello @ioquatix, thank you once again for your dedicated work!

I have trouble understanding the behaviour of Timeout.timeout block when run inside async reactor. The test scenario uses an HTTP call with delayed response but in the real world it could be a call to some LLM which is not unusual to take several seconds.

This works as expected (no timeout set)

# test.rb
require 'async'
require 'net/http'

start = Time.now

Sync do
  Net::HTTP.get(URI 'https://httpbin.org/delay/5')
end

puts "Duration: #{Time.now - start}s"

# => Duration: 5.797459s

This is odd

No timeout error is raised and the total execution time seems to be HTTP call (~5.5s) + timeout (2s)

# test.rb
require 'async'
require 'net/http'

start = Time.now

Sync do
  Timeout.timeout 2 do
    Net::HTTP.get(URI 'https://httpbin.org/delay/5')

    puts "...request finished, no timeout though; in #{Time.now - start}s"
  end
end

puts "Duration: #{Time.now - start}s"

# => ...request finished, no timeout though; in 7.7007s
# Duration: 7.700962s

This works but why?

# test.rb
require 'async'
require 'net/http'

start = Time.now

Sync do
  Timeout.timeout 2, Async::TimeoutError do
    Net::HTTP.get(URI 'https://httpbin.org/delay/5')
  end
end

puts "Duration: #{Time.now - start}s"

with the expected result:

/Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:324:in 'IO::Event::Selector::KQueue#io_wait': execution expired (Async::TimeoutError)
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:324:in 'Async::Scheduler#io_wait'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-protocol-0.2.2/lib/net/protocol.rb:229:in 'IO#wait_readable'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-protocol-0.2.2/lib/net/protocol.rb:229:in 'Net::BufferedIO#rbuf_fill'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-protocol-0.2.2/lib/net/protocol.rb:199:in 'Net::BufferedIO#readuntil'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-protocol-0.2.2/lib/net/protocol.rb:209:in 'Net::BufferedIO#readline'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http/response.rb:159:in 'Net::HTTPResponse.read_status_line'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http/response.rb:147:in 'Net::HTTPResponse.read_new'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:2448:in 'block in Net::HTTP#transport_request'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:2439:in 'Kernel#catch'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:2439:in 'Net::HTTP#transport_request'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:2410:in 'Net::HTTP#request'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:2281:in 'Net::HTTP#request_get'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:826:in 'block in Net::HTTP.get_response'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:1630:in 'Net::HTTP#start'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:1064:in 'Net::HTTP.start'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:824:in 'Net::HTTP.get_response'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/net-http-0.9.1/lib/net/http.rb:805:in 'Net::HTTP.get'
  from test.rb:11:in 'block (2 levels) in <main>'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:645:in 'block in Async::Scheduler#timeout_after'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:626:in 'Async::Scheduler#with_timeout'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:644:in 'Async::Scheduler#timeout_after'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.0/lib/timeout.rb:285:in 'Timeout.timeout'
  from test.rb:8:in 'block in <main>'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:234:in 'block in Async::Task#run'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:512:in 'block in Async::Task#schedule'

I know that Timeout.timeout takes into account the Fiber scheduler and it seems the timeout implementation inside the scheduler depends on the error class being passed to it. Since to my knowledge async's aim is to provide async execution in a transparent manner (i.e. the wrapped code should not know about the async context), passing the very specific Async::TimeoutError (or StandardError or some custom error) is not the ideal solution. Could this be a bug?

Test setup

Ruby 3.4.2
macOS Tahoe
Apple M3

[ioquatix]

There are a number of confusing aspects to the culmination of Timeout.timeout's implementation that ultimately create this odd scenario.

Let me outline what I discovered:

Firstly, Net::HTTP actually tries to catch Timeout::Error and retry the requests:

https://github.com/ruby/ruby/blob/8ca12b54ebe1cbd170108d80c700eea536b6714a/lib/net/http.rb#L2470-L2475

In and of itself, this is what causes the problematic behaviour you see - when we raise Timeout::Error, it actually causes the request to timeout after 2 seconds, and then retries the request which takes 5 seconds = 7 seconds total. Note that net.rb has liberal use of sub-classes of Timeout::Error for it's own ReadTimeout, WriteTimeout etc classes.

Now, why on earth does this happen?

Well, it turns out that previously, this was how Timeout.timeout worked, but because Timeout::Error < RuntimeError, it could be rescued accidentally. Relatively recently, this was addressed in ruby/ruby@e8c9385 - before this, the odd behaviour would probably have also affected non-scheduler Net::HTTP usage - so the above change actually indirectly prevents Net::HTTP from retrying.

So, now I'm wondering, was it the intention of Net::HTTP to rescue Timeout::ExitException? I'm not sure.

In any case, the question remains, why does using Timeout.timeout with the fiber scheduler cause this behaviour? Clearly removing the outer Sync do ... block causes the timeout to trigger successfully. The reason for that is that it looks like the code path for the Fiber scheduler's exception handling was never updated for the new Timeout::ExitException behaviour, it still uses the old Timeout::Error behaviour. Probably, we need to fix timeout.rb in Ruby since this is a behavioural change. We might be able to work around it in the scheduler implementation by detecting this scenario...

cc @jeremyevans

[ioquatix]

After investigating the root cause, I think the best fix is made to timeout gem. Since it's separate from Ruby, once it's fixed, we can update it independently. This should resolve your problem.

[ioquatix]

As ruby/timeout#97 is now merged, we just need to wait for a release of the timeout gem, and after that you need to update it locally, e.g. gem install timeout and that should resolve the issue here. As this isn't something I can fix in the async gem itself, I'll close this issue now.

[agalloch]

Thank you @ioquatix for the lightning fast fix!

[ioquatix]

Okay, can you test https://rubygems.org/gems/timeout/versions/0.6.1 - thanks!

[agalloch]

Hello @ioquatix, I've tested with timeout v0.6.1 and it seems to be working as expected! 🎉

One interesting observation is that I see two different errors in the backtrace - Timeout::ExitException and Timeout::Error, but only the latter could be rescued in the main thread/Fiber:

# test.rb
require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'

  gem 'async'
  gem 'timeout', '0.6.1'
end

require 'async'
require 'net/http'

start = Time.now

Sync do |task|
  Timeout.timeout 2, nil, 'WE GO BOOM IN 2 sec!' do
    Net::HTTP.get(URI 'https://httpbin.org/delay/5')

    puts "...request finished, no timeout though; in #{Time.now - start}s"
  end
end

puts "Duration: #{Time.now - start}s"

produces:

/Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.1/lib/timeout.rb:40:in 'Timeout::Error.handle_timeout': WE GO BOOM IN 2 sec! (Timeout::Error)
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.1/lib/timeout.rb:306:in 'Timeout.timeout'
  from test.rb:18:in 'block in <main>'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:234:in 'block in Async::Task#run'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:512:in 'block in Async::Task#schedule'
/Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:324:in 'IO::Event::Selector::KQueue#io_wait': WE GO BOOM IN 2 sec! (Timeout::ExitException)
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:324:in 'Async::Scheduler#io_wait'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/protocol.rb:229:in 'IO#wait_readable'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/protocol.rb:229:in 'Net::BufferedIO#rbuf_fill'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/protocol.rb:199:in 'Net::BufferedIO#readuntil'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/protocol.rb:209:in 'Net::BufferedIO#readline'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http/response.rb:158:in 'Net::HTTPResponse.read_status_line'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http/response.rb:147:in 'Net::HTTPResponse.read_new'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:2414:in 'block in Net::HTTP#transport_request'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:2405:in 'Kernel#catch'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:2405:in 'Net::HTTP#transport_request'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:2378:in 'Net::HTTP#request'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:2249:in 'Net::HTTP#request_get'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:826:in 'block in Net::HTTP.get_response'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:1626:in 'Net::HTTP#start'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:1064:in 'Net::HTTP.start'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:824:in 'Net::HTTP.get_response'
  from /Users/leuser/.rvm/rubies/ruby-3.4.2/lib/ruby/3.4.0/net/http.rb:805:in 'Net::HTTP.get'
  from test.rb:22:in 'block (2 levels) in <main>'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:645:in 'block in Async::Scheduler#timeout_after'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:626:in 'Async::Scheduler#with_timeout'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/scheduler.rb:644:in 'Async::Scheduler#timeout_after'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.1/lib/timeout.rb:286:in 'block in Timeout.timeout'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.1/lib/timeout.rb:38:in 'Timeout::Error.handle_timeout'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/timeout-0.6.1/lib/timeout.rb:306:in 'Timeout.timeout'
  from test.rb:18:in 'block in <main>'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:234:in 'block in Async::Task#run'
  from /Users/leuser/.rvm/gems/ruby-3.4.2/gems/async-2.36.0/lib/async/task.rb:512:in 'block in Async::Task#schedule'

[ioquatix]

Yes, Timeout::ExitException is an internal exception < Exception, to catch it you'd have to explicitly rescue Exception or rescue Timeout::ExitException. The point is, it generally shouldn't be caught.