io_wait returns a timeout for an IO that is already readable when another fiber runs past the deadline #481

io_wait can report a timeout even though the IO became ready well before the deadline. This happens when another fiber, resumed from the same @selector.select pass, runs longer than the timeout. When that fiber yields, run_once! calls @timers.fire before the selector polls again, so the waiting fiber's timer fires and io_wait returns false while the data is already sitting in the IO.

Reproduction (async 2.46.0, io-event 1.22.3; same result on KQueue, EPoll and Select, Ruby 3.4.6 macOS and 3.4.12 Linux):

require "async"

T0 = Process.clock_gettime(Process::CLOCK_MONOTONIC)
def log(msg) = puts(format("%4.2fs  %s", Process.clock_gettime(Process::CLOCK_MONOTONIC) - T0, msg))

busy_r, busy_w = IO.pipe
waiter_r, waiter_w = IO.pipe
spawn("sleep 0.2; printf x", out: busy_w)   # wakes the busy fiber from the selector at ~0.2s
spawn("sleep 0.5; printf x", out: waiter_w) # the waiter's data arrives at ~0.5s, while busy runs

Sync do |task|
  task.async do
    busy_r.wait_readable
    log("busy: woken by IO, running 2s without yielding")
    finish = Process.clock_gettime(Process::CLOCK_MONOTONIC) + 2
    nil while Process.clock_gettime(Process::CLOCK_MONOTONIC) < finish
  end

  task.async do
    log("waiter: wait_readable(1)")
    result = waiter_r.wait_readable(1)
    log("waiter: wait_readable returned #{result.inspect}; pipe holds #{waiter_r.read_nonblock(1, exception: false).inspect}")
  end
end

0.00s  waiter: wait_readable(1)
0.21s  busy: woken by IO, running 2s without yielding
2.21s  waiter: wait_readable returned nil; pipe holds "x"

The busy fiber has to be resumed from inside @selector.select: if it runs before the reactor polls, the next select(0) sees the pipe and the waiter gets it.

Without a scheduler the same wait cannot time out this way: rb_thread_wait_for_single_fd releases the GVL and blocks in ppoll, so readiness is decided by the kernel and a thread starved of the GVL comes back late but with the data. After an EINTR past the deadline it polls once more with a zero timeout (wait_retryable).

I ran into this with redis-client under a fiber-per-job Sidekiq setup (redis-rb/redis-client#332): a job held the reactor for a few seconds, a sibling fiber's BRPOP reply arrived meanwhile, its read timed out, and redis-client closed the connection with the reply unread. The popped job was lost.

A possible fix is to check the IO once, without blocking, when the timer has expired, before reporting the timeout. This is what I tested:

def io_wait(io, events, timeout = nil)
  fiber = Fiber.current
  expired = false
  raise_on_timeout = timeout.nil? && (timeout = io.timeout)

  timer = @timers.after(timeout) { expired = true; fiber.transfer } if timeout

  until result = @selector.io_wait(fiber, io, events)
    next unless expired
    # The timer can fire after the IO became ready but before the selector
    # polled it again: check once more without blocking.
    return result if (result = Fiber.blocking { io.wait(events, 0) })
    raise ::IO::TimeoutError, "Timeout (#{timeout}s) while waiting for IO to become ready!" if raise_on_timeout
    return false
  end

  result
ensure
  timer&.cancel!
end

With it, the reproduction prints wait_readable returned #<IO:fd 8>; pipe holds "x". It costs nothing unless a timeout actually expires, keeps false for timeouts (#472) and the retry loop (#469), and moves the io.timeout case into the same recheck instead of raising from the timer.

The other place this could be handled is run_once!: when timers are due after select, poll the selector once more with a zero timeout before @timers.fire. That would also cover timeouts raised into a fiber by with_timeout, at the cost of an extra syscall on every pass that fires a timer.

Happy to open a PR with a test for whichever you prefer.