Why is IO::WaitReadable being raised differently for STDOUT than STDERR?

Question

Given that I wish to test non-blocking reads from a long command, I created the following script, saved it as long, made it executable with chmod 755, and placed it in my path (saved as ~/bin/long where ~/bin is in my path).

I am on a *nix variant with ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0] compiled with RVM defaults. I do not use Windows, and am therefore unsure if the test script will work for you if you do.

#!/usr/bin/env ruby

3.times do
  STDOUT.puts 'message on stdout'
  STDERR.puts 'message on stderr'
  sleep 1
end

Why does long_err produce each STDERR message as it is printed by "long"

def long_err( bash_cmd = 'long', maxlen = 4096)
  stdin, stdout, stderr = Open3.popen3(bash_cmd)
  begin
    begin
      puts 'err -> ' + stderr.read_nonblock(maxlen)
    end while true
  rescue IO::WaitReadable
    IO.select([stderr])
    retry
  rescue EOFError
    puts 'EOF'
  end
end

while long_out remains blocked until all STDOUT messages are printed?

def long_out( bash_cmd = 'long', maxlen = 4096)
  stdin, stdout, stderr = Open3.popen3(bash_cmd)
  begin
    begin
      puts 'out -> ' + stdout.read_nonblock(maxlen)
    end while true
  rescue IO::WaitReadable
    IO.select([stdout])
    retry
  rescue EOFError
    puts 'EOF'
  end
end

I assume you will require 'open3' before testing either function.

Why is IO::WaitReadable being raised differently for STDOUT than STDERR?

Workarounds using other ways to start subprocesses also appreciated if you have them.

Answer 1

In most OS's STDOUT is buffered while STDERR is not. What popen3 does is basically open a pipe between the exeutable you launch and Ruby.

Any output that is in buffered mode is not sent through this pipe until either:

1. The buffer is filled (thereby forcing a flush).
2. The sending application exits (EOF is reached, forcing a flush).
3. The stream is explicitly flushed.

The reason STDERR is not buffered is that it's usually considered important for error messages to appear instantly, rather than go for for efficiency through buffering.

So, knowing this, you can emulate STDERR behaviour with STDOUT like this:

#!/usr/bin/env ruby

3.times do
  STDOUT.puts 'message on stdout'
  STDOUT.flush 
  STDERR.puts 'message on stderr'
  sleep 1
end

and you will see the difference.

You might also want to check "Understanding Ruby and OS I/O buffering".

Answer 2

Here's the best I've got so far for starting subprocesses. I launch a lot of network commands so I needed a way to time them out if they take too long to come back. This should be handy in any situation where you want to remain in control of your execution path.

I adapted this from a Gist, adding code to test the exit status of the command for 3 outcomes:

1. Successful completion (exit status 0)
2. Error completion (exit status is non-zero) - raises an exception
3. Command timed out and was killed - raises an exception

Also fixed a race condition, simplified parameters, added a few more comments, and added debug code to help me understand what was happening with exits and signals.

Call the function like this:

output = run_with_timeout("command that might time out", 15)

output will contain the combined STDOUT and STDERR of the command if it completes successfully. If the command doesn't complete within 15 seconds it will be killed and an exception raised.

Here's the function (2 constants you'll need defined at the top):

DEBUG = false        # change to true for some debugging info
BUFFER_SIZE = 4096   # in bytes, this should be fine for many applications

def run_with_timeout(command, timeout)
  output = ''
  tick = 1
  begin
    # Start task in another thread, which spawns a process
    stdin, stderrout, thread = Open3.popen2e(command)
    # Get the pid of the spawned process
    pid = thread[:pid]
    start = Time.now

    while (Time.now - start) < timeout and thread.alive?
      # Wait up to `tick' seconds for output/error data
      Kernel.select([stderrout], nil, nil, tick)
      # Try to read the data
      begin
        output << stderrout.read_nonblock(BUFFER_SIZE)
        puts "we read some data..." if DEBUG
      rescue IO::WaitReadable
        # No data was ready to be read during the `tick' which is fine
        print "."       # give feedback each tick that we're waiting
      rescue EOFError
        # Command has completed, not really an error...
        puts "got EOF." if DEBUG
        # Wait briefly for the thread to exit...
        # We don't want to kill the process if it's about to exit on its
        # own. We decide success or failure based on whether the process
        # completes successfully.
        sleep 1
        break
      end
    end

    if thread.alive?
      # The timeout has been reached and the process is still running so
      # we need to kill the process, because killing the thread leaves
      # the process alive but detached.
      Process.kill("TERM", pid)
    end

  ensure
    stdin.close if stdin
    stderrout.close if stderrout
  end

  status = thread.value         # returns Process::Status when process ends

  if DEBUG
    puts "thread.alive?: #{thread.alive?}"
    puts "status: #{status}"
    puts "status.class: #{status.class}"
    puts "status.exited?: #{status.exited?}"
    puts "status.exitstatus: #{status.exitstatus}"
    puts "status.signaled?: #{status.signaled?}"
    puts "status.termsig: #{status.termsig}"
    puts "status.stopsig: #{status.stopsig}"
    puts "status.stopped?: #{status.stopped?}"
    puts "status.success?: #{status.success?}"
  end

  # See how process ended: .success? => true, false or nil if exited? !true
  if status.success? == true       # process exited (0)
    return output
  elsif status.success? == false   # process exited (non-zero)
    raise "command `#{command}' returned non-zero exit status (#{status.exitstatus}), see below output\n#{output}"
  elsif status.signaled?           # we killed the process (timeout reached)
    raise "shell command `#{command}' timed out and was killed (timeout = #{timeout}s): #{status}"
  else
    raise "process didn't exit and wasn't signaled. We shouldn't get to here."
  end
end

Hope this is useful.