Sleep/IO timeout can return early under concurrent per-fiber timeouts (async 2.42.0)

[cloetzi]

First, full disclaimer, I did use AI to help me reproduce this issue. I can't claim that I fully understand what is at play here, but I did my best to validate that the reproduction steps work and make sense (at least on the surface).

We first noticed the issue when we had a ton of Redis "timeouts" during a performance test without seeing any Redis load, but I am now able to reproduce the issue without any external dependencies.

Without further due, this is the reproduction script I got from the AI:

require "async"
require "socket"

PERIOD  = 0.010 # producer push interval
TIMEOUT = 0.010 # pop timeout, same order as PERIOD so the deadline races a push
VICTIM  = 0.002 # << PERIOD, so the consumer is parked for most of each period
ROUNDS  = 1500

mono = -> { Process.clock_gettime(Process::CLOCK_MONOTONIC) }

run = lambda do |victim|
  q = Thread::Queue.new
  server = TCPServer.new("127.0.0.1", 0)
  client = TCPSocket.new("127.0.0.1", server.addr[1])
  peer = server.accept # kept referenced: a GC'd peer would close and become readable

  anomalies = 0
  could_not_park = 0

  Async do |task|
    producer = task.async do
      ROUNDS.times do
        q.push(:item)
        sleep PERIOD
      end
      q.close
    end

    task.async do
      loop do
        could_not_park += 1 unless q.empty? # a non-empty queue means pop cannot park
        item = q.pop(timeout: TIMEOUT)
        break if item.nil? && q.closed?

        # A correct timer fires late, never early, so any elapsed under the requested
        # wait is already a violation. The socket case also needs !ready, since a
        # readable socket is a legitimate early return.
        t0 = mono.call
        if victim == :sleep
          sleep(VICTIM)
          early = mono.call - t0 < VICTIM
        else
          ready = client.wait_readable(VICTIM)
          early = !ready && mono.call - t0 < VICTIM
        end
        anomalies += 1 if early
      end
    end.wait
    producer.wait
  end

  [anomalies, could_not_park]
ensure
  [client, peer, server].each(&:close)
end

puts "async #{Async::VERSION}, ruby #{RUBY_VERSION}"
%i[sleep socket].each do |victim|
  anomalies, could_not_park = run.call(victim)
  puts "#{victim} victim: #{anomalies} anomalies (expected 0) | could not park: #{could_not_park}/#{ROUNDS} (must be ~0 or the run is invalid)"
end

Example output on my local machine:

async 2.42.0, ruby 4.0.6
sleep victim: 276 anomalies (expected 0) | could not park: 1/1500 (must be ~0 or the run is invalid)
socket victim: 51 anomalies (expected 0) | could not park: 1/1500 (must be ~0 or the run is invalid)

The issue the script outlines is that under some conditions the sleep/wait_readable timeout is not honoured and is returning early.

The AI gave me a whole bunch of more details of what is happening, but I do not have enough context to validate if the explanation is correct, or not, so I won't post it unless you are asking for it.

Please let me know if you need more information (e.g. a script with Redis).