Timeout within a popen works, but popen inside a timeout doesn't?

Question

It's easiest to explain in code:

require 'timeout'

puts "this block will properly kill the sleep after a second"

IO.popen("sleep 60") do |io|
  begin
    Timeout.timeout(1) do
      while (line=io.gets) do
        output += line
      end
    end
  rescue Timeout::Error => ex
    Process.kill 9, io.pid
    puts "timed out: this block worked correctly"
  end
end

puts "but this one blocks for >1 minute"

begin
  pid = 0
  Timeout.timeout(1) do
    IO.popen("sleep 60") do |io|
      pid = io.pid
      while (line=io.gets) do
        output += line
      end
    end
  end
rescue Timeout::Error => ex
  puts "timed out: the exception gets thrown, but much too late"
end

My mental model of the two blocks is identical:

So, what am I missing?

edit: drmaciver suggested on twitter that in the first case, for some reason, the pipe socket goes into non-blocking mode, but in the second it doesn't. I can't think of any reason why this would happen, nor can I figure out how to get the descriptor's flags, but it's at least a plausible answer? Working on that possibility.

Answer 1

Aha, subtle.

There is a hidden, blocking ensure clause at the end of the IO#popen block in the second case. The Timeout::Error is raised raised timely, but you cannot rescue it until execution returns from that implicit ensure clause.

Under the hood, IO.popen(cmd) { |io| ... } does something like this:

def my_illustrative_io_popen(cmd, &block)
  begin
    pio = IO.popen(cmd)
    block.call(pio)      # This *is* interrupted...
  ensure
    pio.close            # ...but then control goes here, which blocks on cmd's termination
  end

and the IO#close call is really more-or-less a pclose(3), which is blocking you in waitpid(2) until the sleeping child exits.

You can verify this like so:

#!/usr/bin/env ruby

require 'timeout'

BEGIN { $BASETIME = Time.now.to_i }

def xputs(msg)
  puts "%4.2f: %s" % [(Time.now.to_f - $BASETIME), msg]
end

begin
  Timeout.timeout(3) do
    begin
      xputs "popen(sleep 10)"
      pio = IO.popen("sleep 10")
      sleep 100                     # or loop over pio.gets or whatever
    ensure
      xputs "Entering ensure block"
      #Process.kill 9, pio.pid      # <--- This would solve your problem!
      pio.close
      xputs "Leaving ensure block"
    end
  end
rescue Timeout::Error => ex
  xputs "rescuing: #{ex}"
end

So, what can you do?

You'll have to do it the explicit way, since the interpreter doesn't expose a way to override the IO#popen ensure logic. You can use the above code as a starting template and uncomment the kill() line, for example.

Answer 2

In the first block, the timeout is raised in the child, killing it and returning control to the parent. In the second block, the timeout is raised in the parent. The child never gets the signal.

See io.c https://github.com/ruby/ruby/blob/trunk/io.c#L6021 and timeout.rb https://github.com/ruby/ruby/blob/trunk/lib/timeout.rb#L51