Inconsistent Timeout::timeout and rescue Timeout::Error behavior

Question

I'm using Timeout::timeout(1) for a process that takes longer than 1 second, though it only occasionally triggers a timeout. When it does, rescue captures it in different ways each time. Here's a sample of my code:

require 'timeout'
...
begin
  status = Timeout::timeout(1) {
    open(file_url) do |foo|
      feed = RSS::Parser.parse(foo)
      some_method_call(arg1, arg2)
      #other stuff
    end
  }
rescue Timeout::Error
  Rails.logger.debug "Timeout"
  return nil
rescue Exception => ex
  Rails.logger.debug "EXCEPTION - #{ex.message}"
  return nil
end

Here are the three scenarios I encounter with the same input:

Process runs to completion and takes longer than 60 seconds
Process times out and hangs, printing only execution expired in development.log
Process times out, is rescued properly, prints "Timeout" in development.log, and returns nil

Why is this so inconsistent?

UPDATE

After reducing the timeout to 0.0001s, the process is timing out consistently and as expected. It seems that the open(file_url) block was opening faster than 1 second, and despite everything within the block taking more than 1 second, the Timeout was only triggered if the opening itself took longer than 1 second.

This however did not explain the execution expired exception. To test this, I moved the Timeout::timeout(0.0001) to within the open block. The code looks like the following:

require 'timeout'
...
begin
  open(file_url) do |foo|
    status = Timeout::timeout(0.0001) do
      begin
        feed = RSS::Parser.parse(foo)
        some_method_call(arg1, arg2)
        #other stuff
      rescue Timeout::Error
        Rails.logger.debug "Timeout 2"
      rescue Exception => ex
        Rails.logger.debug "EXCEPTION 2 - #{ex.message}"
      end
    end
  end
rescue Timeout::Error
  Rails.logger.debug "Timeout"
  return nil
rescue Exception => ex
  Rails.logger.debug "EXCEPTION - #{ex.message}"
  return nil
end

Now, I'm consistently receiving the output EXCEPTION 2 - execution expired. Why is it that the Timeout::Error is not being triggered here?

This looks related: http://stackoverflow.com/questions/4637282/ruby-timeouttimeout-doesnt-fire-exception-and-doesnt-return-what-documented?rq=1 — Nick, Jul 11 '12 at 15:37
@Stefan - I tried testing for exceptions inside, and I am indeed receiving exceptions within. Check the updated question. — Nick, Jul 11 '12 at 16:15

score 1 · Answer 1 · answered Jul 11 '12 at 19:43

1

Your inner

rescue Exception => ex
  Rails.logger.debug "EXCEPTION 2 - #{ex.message}"
end

keeps the outer timeoutblock from raising Timeout::Error.

Removing that rescuestatement should do the trick.

If you really need to catch any exception, replace it with:

rescue StandardError => ex
  Rails.logger.debug "EXCEPTION 2 - #{ex.message}"
end

answered Jul 11 '12 at 19:43

Stefan

109,145
14
143
218

Shouldn't the inner `timeout` block have raised an exception? – Nick Jul 18 '12 at 13:59

score 1 · Answer 2 · answered Nov 16 '13 at 04:31

Internally (within the Timeout block) Timeout does not use Timeout::Error. If it did, then every garden-variety rescue would catch it, and you don't want that. So it creates a new Exception and uses that, so that it hopefully blows through all normal error handling and actually makes the code stop running.

Check out the timeout.rb code in ruby200/lib/ruby/2.0.0. It's quite short, and pretty informative.

In particular, you can pass your own Exception in as the second parameter of Timeout::timeout, and Timeout will use that. So you can catch it inside your code, if you want.

Note that Logger currently traps all exceptions that happen while writing, and doesn't re-raise, so it breaks Timeout. I've filed a bug report.

Inconsistent Timeout::timeout and rescue Timeout::Error behavior

2 Answers2