[ruby-core:58374] [ruby-trunk - Bug #9115][Open] Logger traps all exceptions; breaks Timeout

[ruby-core:58374] [ruby-trunk - Bug #9115][Open] Logger traps all exceptions; breaks Timeout

[cphoenix (Chris Phoenix)]

Issue #9115 has been reported by cphoenix (Chris Phoenix).

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115

Author: cphoenix (Chris Phoenix)
Status: Open
Priority: Normal
Assignee: 
Category: 
Target version: 
ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN


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




-- 
http://bugs.ruby-lang.org/

[ruby-core:58385] [ruby-trunk - Bug #9115] Logger traps all exceptions; breaks Timeout

[cphoenix (Chris Phoenix)]

Issue #9115 has been updated by cphoenix (Chris Phoenix).


...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.

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-42981

Author: cphoenix (Chris Phoenix)
Status: Open
Priority: Normal
Assignee: 
Category: 
Target version: 
ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN


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




-- 
http://bugs.ruby-lang.org/

[ruby-core:64346] [ruby-trunk - Bug #9115] Logger traps all exceptions; breaks Timeout

[aaron]

Issue #9115 has been updated by Aaron Stone.


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?

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-48325

* Author: Chris Phoenix
* Status: Open
* Priority: Normal
* Assignee: 
* Category: 
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:64753] [ruby-trunk - Bug #9115] Logger traps all exceptions; breaks Timeout

[billpaulson]

Issue #9115 has been updated by Bill Paulson.


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

~~~



----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-48642

* Author: Chris Phoenix
* Status: Open
* Priority: Normal
* Assignee: 
* Category: 
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:69940] [Ruby trunk - Bug #9115] Logger traps all exceptions; breaks Timeout

[stefano.tortarolo]

Issue #9115 has been updated by Stefano Tortarolo.


I confirm that this bug is reproducible up to 2.2 and it's pretty easy to trigger.

~~~
require 'timeout'
require 'logger'

class MyExc < RuntimeError; end

def long_call(logger)
  Timeout.timeout(3, MyExc) do
    a = 1
    loop do
      a += 1
      logger.warn "Test #{a}"
    end
  end
end
~~~

Aaron Stone is right though that using 2.1+ it would work if you don't provide a custom exception or if your exception inherits from TimeoutError.

Beware that it must inherit from Object::TimeoutError and not Timeout::Error.

Having said that, it'd be nice to have a proper fix at logger.rb level.

@Bill, I don't think your code would fix it though, because the underlying device might throw a different exception.

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-53367

* Author: Chris Phoenix
* 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
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:69979] [Ruby trunk - Bug #9115] Logger traps all exceptions; breaks Timeout

[stefano.tortarolo]

Issue #9115 has been updated by Stefano Tortarolo.


Correction: providing an exception to Timeout#timeout would break it also in trunk.

It seems that by design inner blocks are able to rescue the exception provided to that method.

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-53416

* Author: Chris Phoenix
* 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
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:94391] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout

[merch-redmine]

Issue #9115 has been updated by jeremyevans0 (Jeremy Evans).

Backport deleted (1.9.3: UNKNOWN, 2.0.0: UNKNOWN)
Assignee set to sonots (Naotoshi Seo)
Status changed from Open to Assigned

It makes sense for Logger to handle all exceptions by default, as you don't want Logger breaking otherwise working code.  So the default behavior is expected and not a bug.

I think the best way to handle this is to allow the user to specify exception classes they would like reraised instead of swallowed.  I've added a pull request that implements this: https://github.com/ruby/logger/pull/37

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-80807

* Author: cphoenix (Chris Phoenix)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:94393] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout

[samuel]

Issue #9115 has been updated by ioquatix (Samuel Williams).


> It makes sense for Logger to handle all exceptions by default

I'm not sure I agree with this. There must be some well-defined set of exceptions that could be raised by the code it's executing that should be handled/ignored, e.g. `IOError`, EPERM, ENOSPC, etc. I think it's going to be much better to solve this problem by catching only specific errors that related to the operations that might fail.

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-80810

* Author: cphoenix (Chris Phoenix)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:94443] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout

[naruse]

Issue #9115 has been updated by naruse (Yui NARUSE).


See the code again before discuss.

```ruby
    def write(message)
      begin
        synchronize do
          if @shift_age and @dev.respond_to?(:stat)
            begin
              check_shift_log
            rescue
              warn("log shifting failed. #{$!}")
            end
          end
          begin
            @dev.write(message)
          rescue
            warn("log writing failed. #{$!}")
          end
        end
      rescue Exception => ignored
        warn("log writing failed. #{ignored}")
      end
    end
```
https://github.com/ruby/ruby/blob/5a384e2c08704dc7af9d8d3bdfc475eb8c0723aa/lib/logger/log_device.rb#L29-L48

With the code, the intention of `rescue Exception` is clear. It wants to rescue exceptions which is raised by `synchronize`.

And note that `synchronize` is Monitor's and it only raises ThreadError.
https://github.com/ruby/ruby/blob/master/lib/monitor.rb
I don't understand why it loosely rescues all exceptions.

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-80869

* Author: cphoenix (Chris Phoenix)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/

[ruby-core:94445] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout

[naruse]

Issue #9115 has been updated by naruse (Yui NARUSE).


There're also rescue-clauses for `check_shift_log` and `@dev.write(message)`.
They may raise various exceptions and logger.rb never knows that.

Explicitly passing those exceptions are general way, but are there any exceptions other than the family of Timeout::Error?

----------------------------------------
Bug #9115: Logger traps all exceptions; breaks Timeout
https://bugs.ruby-lang.org/issues/9115#change-80871

* Author: cphoenix (Chris Phoenix)
* Status: Assigned
* Priority: Normal
* Assignee: sonots (Naotoshi Seo)
* Target version: 
* ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32]
* Backport: 
----------------------------------------
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





-- 
https://bugs.ruby-lang.org/