Bug #9115

Logger traps all exceptions; breaks Timeout

Added by Chris Phoenix over 1 year ago. Updated 8 months ago.

[ruby-core:58374]
Status:Open
Priority:Normal
Assignee:-
ruby -v:ruby 2.0.0p247 (2013-06-27) [i386-mingw32] Backport:1.9.3: UNKNOWN, 2.0.0: UNKNOWN

Description

Line 577-579 of logger.rb

  rescue Exception => ignored
    warn("log writing failed. #{ignored}")
  end

Thus, when the system times out in the middle of writing a log message, it warns "log writing failed. execution expired" and just keeps right on running.

This is true in 1.9.3 as well. I haven't looked at older versions.

Pardon me while I go grep "rescue Exception" in the entire Ruby codebase, and see whether I can reliably use Timeout at all...

OK, you might check out C:\Ruby200\lib\ruby\gems\2.0.0\gems\activerecord-3.2.13\lib\active_record\railties\databases.rake

All the other "rescue Exception" seem to re-raise it, except maybe C:\Ruby200\lib\ruby\2.0.0\xmlrpc\server.rb and C:\Ruby200\lib\ruby\gems\2.0.0\gems\activesupport-3.2.13\lib\active_support\callbacks.rb

History

#1 Updated by Chris Phoenix over 1 year ago

...I guess my search was broken. I did another and found a whole lot of "rescue exception" that don't seem to always re-raise. But the logger is a big one because it's supposed to be usable everywhere, and someone who logs a lot will run into this bug.

#2 Updated by Aaron Stone 8 months ago

The behavior has changed in Ruby 2.1, and the default rescue no longer rescues Timeout unless Timeout was given an explicit exception class to raise. Could you try Ruby 2.1 and see if it behaves according to your expectation here?

#3 Updated by Bill Paulson 8 months ago

The source code for 2.1.2 doesn't seem to have changed: the LogDevice::write method still does a rescue Exception and ignores the result.
Our application ran into this problem when one thread raises an exception in another thread that's doing a LogDevice::write(). The exception is supposed to be handled at a higher level, so write() rescuing it and ignoring it causes our application to hang.
A write() method without this problem looks like

  def write(message)
    @mutex.synchronize do
      if @shift_age and @dev.respond_to?(:stat)
        begin
          check_shift_log
        rescue IOError
          warn("log shifting failed. #{$!}")
        end
      end
      begin
        @dev.write(message)
      rescue IOError
        warn("log writing failed. #{$!}")
      end
    end
  end

Also available in: Atom PDF