Search code examples
rubyexceptionrescue

"rescue Exception" not rescuing Timeout::Error in net_http


We appear to have a situation where rescue Exception is not catching a particular exception.

I'm trying to send an email alert about any exception that occurs, and then continue processing. We've put in the requisit handling of intentional exits. We want the loop to keep going, after alerting us, for anything else.

The exception that is not being caught is ostensibly Timeout::Error, according to the stack trace.

Here is the stack trace, with references to my intermediate code removed (the last line of my code is request.rb:93):

/opt/ruby-enterprise/lib/ruby/1.8/timeout.rb:64:in `rbuf_fill': execution expired (Timeout::Error)
    from /opt/ruby-enterprise/lib/ruby/1.8/net/protocol.rb:134:in `rbuf_fill'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/protocol.rb:116:in `readuntil'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/protocol.rb:126:in `readline'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:2028:in `read_status_line'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:2017:in `read_new'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:1051:in `__request__'
    from /mnt/data/blueleaf/releases/20150211222522/vendor/bundle/ruby/1.8/gems/rest-client-1.6.7/lib/restclient/net_http_ext.rb:51:in `request'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:1037:in `__request__'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:543:in `start'
    from /opt/ruby-enterprise/lib/ruby/1.8/net/http.rb:1035:in `__request__'
    from /mnt/data/blueleaf/releases/20150211222522/vendor/bundle/ruby/1.8/gems/rest-client-1.6.7/lib/restclient/net_http_ext.rb:51:in `request'
    from /mnt/data/blueleaf/releases/20150211222522/app/models/dst/request.rb:93:in `send'
    [intermediate code removed]
    from script/dst_daemon.rb:49
    from script/dst_daemon.rb:46:in `each'
    from script/dst_daemon.rb:46
    from /opt/ruby-enterprise/lib/ruby/1.8/benchmark.rb:293:in `measure'
    from script/dst_daemon.rb:45
    from script/dst_daemon.rb:24:in `loop'
    from script/dst_daemon.rb:24
    from script/runner:3:in `eval'
    from /mnt/data/blueleaf/releases/20150211222522/vendor/bundle/ruby/1.8/gems/rails-2.3.14/lib/commands/runner.rb:46
    from script/runner:3:in `require'

Here is request.rb#send, with line 93 indicated with a comment:

  def send
    build

    uri = URI.parse([DST::Request.configuration[:prefix], @path].join('/'))
    https = Net::HTTP.new(uri.host, uri.port)
    https.use_ssl = true
    https.verify_mode = OpenSSL::SSL::VERIFY_NONE
    https_request = Net::HTTP::Post.new(uri.request_uri.tap{|e| debug_puts "\nURL: #{e}, host:#{uri.host}"})
    # line 93:
    https_request.body = request 
    response = https.request(https_request)
    # the rest should be irrelevant

Here is dst_daemon.rb; line 49 is indicated with a comment, and the rescue Exception that should catch anything other than deliberate interrupts is near the end:

DST::Request.environment = :production
class DST::Request::RequestFailed < Exception; end

Thread.abort_on_exception = true
SEMAPHORE = 'import/dst/start.txt' unless defined?(SEMAPHORE)
DEBUG_DST = 'import/dst/debug.txt' unless defined?(DEBUG_DST)
DEBUG_LOG = 'import/dst/debug.log' unless defined?(DEBUG_LOG)

def debug_dst(*args)
  File.open(DEBUG_LOG, 'a') do |f|
    f.print "#{Time.now.localtime}: "
    f.puts(*args)
  end if debug_dst?
end

def debug_dst?
  File.exist?(DEBUG_DST)
end

dst_ids = [Institution::BAA_DST_WS_CLIENT_ID, Institution::BAA_DST_WS_DEALER_ID]
institutions = Institution.find_all_by_baa_api_financial_institution_id(dst_ids)
DST::Collector.prime_key!

loop do
  begin
    if File.exist?(SEMAPHORE)
      debug_dst 'waking up...'

      custodians = InstitutionAccount.acts_as_baa_custodian.
        find_all_by_institution_id(institutions).select(&:direct?)
      good,bad = custodians.partition do |c|
        c.custodian_users.map{|e2|e2.custodian_passwords.count(:conditions => ['expired is not true']) == 1}.all?
      end
      if bad.present?
        msg = "  skipping: \n"
        bad.each do |c|
          msg += "    #{c.user.full_name_or_email}, custodian id #{c.id}: "
          c.custodian_users.each{|cu| msg += "#{cu.username}:#{cu.custodian_passwords.count(:conditions => ['expired is not true'])}; "}
          msg += "\n"
        end
        AdminSimpleMailer.deliver_generic_mail("DST Daemon skipping #{bad.size} connections", msg)
        debug_dst msg
      end

      Benchmark.measure do
        good.each do |custodian|
          begin
            debug_dst "  collecting for: #{custodian.name}, #{custodian.subtitle}, (#{custodian.id.inspect})"
            # line 49:
            DST::Collector.new(custodian, 0).collect!
          rescue DST::Request::PasswordFailed, DST::Request::RequestFailed  => e
            message = e.message + "\n\n" + e.backtrace.join("\n")
            AdminSimpleMailer.deliver_generic_mail("DST Daemon Connection Failed #{e.class.name}", message)
            debug_dst "  skipping, #{e.class}"
          end
        end
      end.tap{|duration| debug_dst "collection done, duration #{duration.real.to_f/60} minutes. importing" }

      DST::Strategy.new(Date.yesterday, :recompute => true).import!
      debug_dst 'import done.'

      rm SEMAPHORE, :verbose => debug_dst?
    else
      debug_dst 'sleeping.' if Time.now.strftime("%M").to_i % 5 == 0
    end
  rescue SystemExit, Interrupt
    raise
  rescue Exception => e
    message = e.message + "\n\n" + e.backtrace.join("\n")
    AdminSimpleMailer.deliver_generic_mail("DST Daemon Exception #{e.class.name}", message)
  ensure
    sleep 60
  end
end

Shouldn't it be impossible for this loop to exit with a stack trace other than from SystemExit or Interrupt?


Solution

  • As you probably know already, calling raise inside a rescue block will raise the exception to the caller. Since Timeout::Error is an Interrupt in ruby 1.8*, the timeout exception raised by net_http gets handled in the rescue SystemExit, Interrupt block rather than in the following rescue Exception => e.

    To verify that Timeout::Error is an Interrupt, just evaluate Timeout::Error.ancestors. What you get out of that is the hierarchy of classes Timeout::Error inherits from.

    *this is no longer the case in ruby1.9.