Feature #6647

Exceptions raised in threads should be logged

Added by Charles Nutter almost 2 years ago. Updated 3 months ago.

[ruby-core:45864]
Status:Assigned
Priority:Normal
Assignee:Yukihiro Matsumoto
Category:core
Target version:current: 2.2.0

Description

Many applications and users I have dealt with have run into bugs due to Ruby's behavior of quietly swallowing exceptions raised in threads. I believe this is a bug, and threads should always at least log exceptions that bubble all the way out and terminate them.

The implementation should be simple, but I'm not yet familiar enough with the MRI codebase to provide a patch. The exception logging should be logged in the same way top-level exceptions get logged, but perhaps with information about the thread that was terminated because of the exception.

Here is a monkey patch that simulates what I'm hoping to achieve with this bug:

class << Thread
alias old_new new

def new(args, &block)
old_new(
args) do |bargs|
begin
block.call(
bargs)
rescue Exception => e
raise if Thread.abortonexception || Thread.current.abortonexception
puts "Thread for block #{block.inspect} terminated with exception: #{e.message}"
puts e.backtrace.map {|line| " #{line}"}
end
end
end
end

Thread.new { 1 / 0 }.join
puts "After thread"

END

Output:

system ~/projects/jruby $ ruby threaderror.rb
Thread for block #<Proc:0x000000010d008a80@thread
error.rb:17> terminated with exception: divided by 0
threaderror.rb:17:in /'
thread_error.rb:17
thread_error.rb:7:in
call'
thread
error.rb:7:in new'
thread_error.rb:5:in
initialize'
threaderror.rb:5:in old_new'
thread_error.rb:5:in
new'
thread
error.rb:17
After thread

History

#1 Updated by Charles Nutter almost 2 years ago

FWIW, precedent: Java threads log their exceptions by default. I have never found the feature to be a bother, and it makes it nearly impossible to ignore fatally-flawed thread logic that spins up and fails lots of threads.

#2 Updated by Eero Saynatkari almost 2 years ago

headius (Charles Nutter) wrote:

Many applications and users I have dealt with have run into bugs due to Ruby's behavior of quietly swallowing exceptions raised in threads. I believe this is a bug, and threads should always at least log exceptions that bubble all the way out and terminate them.

I have had to set .abortonexception more times than I care to remember.

  rescue Exception => e
    raise if Thread.abort_on_exception || Thread.current.abort_on_exception
    puts "Thread for block #{block.inspect} terminated with exception: #{e.message}"
    puts e.backtrace.map {|line| "  #{line}"}

$stderr/warn, but this would improve the current situation significantly.

Can significant upgrade problems be expected if .abortonexception defaulted to true? This would seem to be the behaviour to suit most users.

#3 Updated by Alex Young almost 2 years ago

On 25/06/12 23:44, rue (Eero Saynatkari) wrote:

Issue #6647 has been updated by rue (Eero Saynatkari).

headius (Charles Nutter) wrote:

Many applications and users I have dealt with have run into bugs due to Ruby's behavior of quietly swallowing exceptions raised in threads. I believe this is a bug, and threads should always at least log exceptions that bubble all the way out and terminate them.

I have had to set .abortonexception more times than I care to remember.

Agreed. It's one of the things I check for in code review. Consider
this a +1 from me.

   rescue Exception =>  e
     raise if Thread.abort_on_exception || Thread.current.abort_on_exception
     puts "Thread for block #{block.inspect} terminated with exception: #{e.message}"
     puts e.backtrace.map {|line| "  #{line}"}

$stderr/warn, but this would improve the current situation significantly.

Can significant upgrade problems be expected if .abortonexception defaulted to true? This would seem to be the behaviour to suit most users.

That sounds a little extreme, although I wouldn't object. I'd be happy
with them not being silently swallowed.

--
Alex


Bug #6647: Exceptions raised in threads should be logged
https://bugs.ruby-lang.org/issues/6647#change-27456

Author: headius (Charles Nutter)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: head

Many applications and users I have dealt with have run into bugs due to Ruby's behavior of quietly swallowing exceptions raised in threads. I believe this is a bug, and threads should always at least log exceptions that bubble all the way out and terminate them.

The implementation should be simple, but I'm not yet familiar enough with the MRI codebase to provide a patch. The exception logging should be logged in the same way top-level exceptions get logged, but perhaps with information about the thread that was terminated because of the exception.

Here is a monkey patch that simulates what I'm hoping to achieve with this bug:

class<< Thread
alias old_new new

def new(args,&block)
old_new(
args) do |bargs|
begin
block.call(
bargs)
rescue Exception => e
raise if Thread.abortonexception || Thread.current.abortonexception
puts "Thread for block #{block.inspect} terminated with exception: #{e.message}"
puts e.backtrace.map {|line| " #{line}"}
end
end
end
end

Thread.new { 1 / 0 }.join
puts "After thread"

END

Output:

system ~/projects/jruby $ ruby threaderror.rb
Thread for block #<Proc:0x000000010d008a80@thread
error.rb:17> terminated with exception: divided by 0
threaderror.rb:17:in /'
thread_error.rb:17
thread_error.rb:7:in
call'
thread
error.rb:7:in new'
thread_error.rb:5:in
initialize'
threaderror.rb:5:in old_new'
thread_error.rb:5:in
new'
thread
error.rb:17
After thread

#4 Updated by Eric Wong almost 2 years ago

Alex Young alex@blackkettle.org wrote:

On 25/06/12 23:44, rue (Eero Saynatkari) wrote:

Issue #6647 has been updated by rue (Eero Saynatkari).

$stderr/warn, but this would improve the current situation significantly.

Can significant upgrade problems be expected if .abortonexception defaulted to true? This would seem to be the behaviour to suit most users.

That sounds a little extreme, although I wouldn't object. I'd be
happy with them not being silently swallowed.

I think aborting the whole process is extreme (though, I usually do
it myself).

I would very much like to see this via $stderr/warn, though.

#5 Updated by Eero Saynatkari almost 2 years ago

normalperson (Eric Wong) wrote:

Alex Young alex@blackkettle.org wrote:

On 25/06/12 23:44, rue (Eero Saynatkari) wrote:

Issue #6647 has been updated by rue (Eero Saynatkari).

$stderr/warn, but this would improve the current situation significantly.

Can significant upgrade problems be expected if .abortonexception defaulted to true? This would seem to be the behaviour to suit most users.

That sounds a little extreme, although I wouldn't object. I'd be
happy with them not being silently swallowed.

I think aborting the whole process is extreme (though, I usually do
it myself).

You are probably correct. Reconsidering the issue, the benefit of raising
is probably not enough to offset that, thus leaving the $stderr/warn as the
better choice.

Eero

#6 Updated by Hiroshi Nakamura almost 2 years ago

  • Category set to core
  • Status changed from Open to Assigned
  • Assignee set to Yukihiro Matsumoto
  • Target version set to 2.0.0

Discussions ad CRuby dev meeting at 14th July.

  • We can understand the requirement. (We understood that the requirement is dumping something without raising when Thread#abortonexception = false)
  • Writing to STDERR could cause problem with existing applications so we should take care about it.
  • rbwarn() instead of puts would be good because we already using rbwarns.

Matz, do you mind if we dump Thread error with rbwarn if Thread#aborton_exception = false?

#7 Updated by Charles Nutter over 1 year ago

Any update on this?

#8 Updated by Charles Nutter over 1 year ago

Ping! This came up in JEG's talk at Aloha RubyConf as a recommendation (specifically, set abortonexception globally to ensure failed threads don't quietly disappear). Ruby should not allow threads to quietly fail.

#9 Updated by Motohiro KOSAKI over 1 year ago

I think "exception raised" callback is better way because an ideal output (both format and output device) depend on an application. It should be passed a raised exception.

#10 Updated by Alex Young over 1 year ago

On 15/10/12 03:24, kosaki (Motohiro KOSAKI) wrote:

Issue #6647 has been updated by kosaki (Motohiro KOSAKI).

I think "exception raised" callback is better way because an ideal output (both format and output device) depend on an application. It should be passed a raised exception.

This, along with a sensible default that displays something to stderr,
would be absolutely ideal from my point of view.

--
Alex


Bug #6647: Exceptions raised in threads should be logged
https://bugs.ruby-lang.org/issues/6647#change-30689

Author: headius (Charles Nutter)
Status: Assigned
Priority: Normal
Assignee: matz (Yukihiro Matsumoto)
Category: core
Target version: 2.0.0
ruby -v: head

Many applications and users I have dealt with have run into bugs due to Ruby's behavior of quietly swallowing exceptions raised in threads. I believe this is a bug, and threads should always at least log exceptions that bubble all the way out and terminate them.

The implementation should be simple, but I'm not yet familiar enough with the MRI codebase to provide a patch. The exception logging should be logged in the same way top-level exceptions get logged, but perhaps with information about the thread that was terminated because of the exception.

Here is a monkey patch that simulates what I'm hoping to achieve with this bug:

class<< Thread
alias old_new new

def new(args,&block)
old_new(
args) do |bargs|
begin
block.call(
bargs)
rescue Exception => e
raise if Thread.abortonexception || Thread.current.abortonexception
puts "Thread for block #{block.inspect} terminated with exception: #{e.message}"
puts e.backtrace.map {|line| " #{line}"}
end
end
end
end

Thread.new { 1 / 0 }.join
puts "After thread"

END

Output:

system ~/projects/jruby $ ruby threaderror.rb
Thread for block #<Proc:0x000000010d008a80@thread
error.rb:17> terminated with exception: divided by 0
threaderror.rb:17:in /'
thread_error.rb:17
thread_error.rb:7:in
call'
thread
error.rb:7:in new'
thread_error.rb:5:in
initialize'
threaderror.rb:5:in old_new'
thread_error.rb:5:in
new'
thread
error.rb:17
After thread

#11 Updated by Charles Nutter over 1 year ago

I started prototyping a callback version and ran into some complexities I could not easily resolve:

  • How does abortonexception= interact with a callback system? ** I tried implementing abortonexception=true to use a builtin callback that raises in Thread.main, but should abortonexception=true blow away a previously-set callback? ** Similarly: should abortonexception=false reset to a do-nothing callback? ** If neither of these, how do we combine callback and abortonexception behavior?
  • Seems like there should be a Thread.defaultexceptionhandler you can set once for all future threads.

My concern is that bikeshedding a callback API -- as useful as it might be -- will cause further delays in the more important behavior of having threads report that they terminated due to an exception.

#12 Updated by Charles Nutter over 1 year ago

Ping!

#13 Updated by Charles Nutter over 1 year ago

Checking in on this again. Can we at least agree it should happen for 2.0.0? Perhaps Matz should review this?

#14 Updated by Yusuke Endoh over 1 year ago

  • Tracker changed from Bug to Feature

headius (Charles Nutter) wrote:

Can we at least agree it should happen for 2.0.0?

No, objection. This looks to me nothing except for a feature request.
I cannot estimate the impact how writing to stderr affects existing applications.
There is a workaround.
I don't think that your concern is so significant that we should address by changing the spec from now.

Moving to the feature tracker and setting to next minor.

Yusuke Endoh mame@tsg.ne.jp

#15 Updated by Yusuke Endoh over 1 year ago

  • Target version changed from 2.0.0 to next minor

#16 Updated by Charles Nutter 7 months ago

So, can we do this for 2.1? I have heard from many other users that really would like exceptions bubbling out of threads to be reported in some way. We have had numerous bug reports relating to code where threads disappear without a trace.

#17 Updated by Avdi Grimm 7 months ago

This would indeed eliminate a huge amount of confusion for people getting
started with threads. Or for people years of experience with threads, for
that matter...

On Fri, Sep 27, 2013 at 7:18 AM, headius (Charles Nutter) <
headius@headius.com> wrote:

Issue #6647 has been updated by headius (Charles Nutter).

So, can we do this for 2.1? I have heard from many other users that really
would like exceptions bubbling out of threads to be reported in some way.
We have had numerous bug reports relating to code where threads disappear

without a trace.

Feature #6647: Exceptions raised in threads should be logged
https://bugs.ruby-lang.org/issues/6647#change-42043

Author: headius (Charles Nutter)
Status: Assigned
Priority: Normal
Assignee: matz (Yukihiro Matsumoto)
Category: core
Target version: next minor

Many applications and users I have dealt with have run into bugs due to
Ruby's behavior of quietly swallowing exceptions raised in threads. I
believe this is a bug, and threads should always at least log exceptions
that bubble all the way out and terminate them.

The implementation should be simple, but I'm not yet familiar enough with
the MRI codebase to provide a patch. The exception logging should be logged
in the same way top-level exceptions get logged, but perhaps with
information about the thread that was terminated because of the exception.

Here is a monkey patch that simulates what I'm hoping to achieve with this
bug:

class << Thread
alias old_new new

def new(args, &block)
old_new(
args) do |bargs|
begin
block.call(
bargs)
rescue Exception => e
raise if Thread.abortonexception ||
Thread.current.abortonexception
puts "Thread for block #{block.inspect} terminated with exception:
#{e.message}"
puts e.backtrace.map {|line| " #{line}"}
end
end
end
end

Thread.new { 1 / 0 }.join
puts "After thread"

END

Output:

system ~/projects/jruby $ ruby threaderror.rb
Thread for block #<Proc:0x000000010d008a80@thread
error.rb:17> terminated
with exception: divided by 0
threaderror.rb:17:in /'
thread_error.rb:17
thread_error.rb:7:in
call'
thread
error.rb:7:in new'
thread_error.rb:5:in
initialize'
threaderror.rb:5:in old_new'
thread_error.rb:5:in
new'
thread
error.rb:17
After thread

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

--
Avdi Grimm
http://avdi.org

I only check email twice a day. to reach me sooner, go to
http://awayfind.com/avdi

#18 Updated by Koichi Sasada 7 months ago

  • Target version changed from next minor to 2.1.0

#19 Updated by Koichi Sasada 7 months ago

(2013/09/27 20:18), headius (Charles Nutter) wrote:

So, can we do this for 2.1? I have heard from many other users that really would like exceptions bubbling out of threads to be reported in some way. We have had numerous bug reports relating to code where threads disappear without a trace.

I'll ask matz.

Does JRuby log it already?
Any problem on your experience if you have?

--
// SASADA Koichi at atdot dot net

#20 Updated by Charles Nutter 7 months ago

We do not currently log it, but the patch to do so is trivial.

https://gist.github.com/6764310

I'm running tests now to confirm it doesn't break anything.

#21 Updated by Charles Nutter 7 months ago

Testing seems to indicate this is a pretty safe change, and it just makes the debug-logged exception output be logged any time abortonexception is not true.

#22 Updated by Akira Tanaka 7 months ago

In the yesterday's meeting,
https://bugs.ruby-lang.org/projects/ruby/wiki/DevelopersMeeting20131001Japan
we discussed this issue.

We found that message at thread exiting with exception have a problem.
The thread can be joined after exit and the exception may be handled by joined thread.

% ruby -e '
t = Thread.new {
raise "foo"
}
sleep 1 # the thread exits with an exception.
begin
t.join
rescue
p $! # something to do with the exception
end
'
#

If thread exiting with exception outputs a message,
there is no way to disable to it.

So, the message should be delayed until Ruby is certain that
the thread is not joined.
This means the message should be output at the thread is collected by GC.

#23 Updated by Charles Nutter 7 months ago

akr (Akira Tanaka) wrote:

In the yesterday's meeting,
https://bugs.ruby-lang.org/projects/ruby/wiki/DevelopersMeeting20131001Japan
we discussed this issue.

We found that message at thread exiting with exception have a problem.
The thread can be joined after exit and the exception may be handled by joined thread.
...
If thread exiting with exception outputs a message,
there is no way to disable to it.

So, the message should be delayed until Ruby is certain that
the thread is not joined.
This means the message should be output at the thread is collected by GC.

GC is a pretty fuzzy time boundary, but it's not terrible. Handling it will mean some finalization requirement for threads to say "hey, I just GCed this thread that died due to an unhandled exception". I feel like something more explicit is needed.

I guess I need to think about this. Some of the cases I want to fix -- where threads are spun up and left to do their own work -- this might be acceptable. But many users will keep references to worker threads they start in order to explicitly stop them on shutdown or other events. In those cases, the thread will be hard referenced and never GCed...and there will be no indication that the thread has died.

Perhaps this could be an on-by-default flag? It would require very little work to add something like:

class Thread
def reportonexception=(report) ..
end

...where the default is true. Going forward, this would be like having the debug output of a thread-killing exception always happen, but you could turn it off. That would address your concern about not being able to silence it.

The workflow would go like this:

If you are spinning up a thread to do background work and don't plan to check on it...

  • Spin up the thread
  • Store it in a list if you like
  • A message will be reported if the thread dies in an exceptional way

If you are spinning up a thread you plan to join on at some time in the future...

  • Spin up the thread
  • Set Thread#reportonexception = false
  • Join at your leisure...no message will be reported

This at least allows users to say "I mean to pick up this thread's results later...don't report an error" without having hard-referenced threads die silently.

Is this a reasonable compromise?

#24 Updated by Koichi Sasada 7 months ago

FYT:
On pthread, there is pthreaddetach() which declares nobody join on this thread.
In other words, pthread
detach() is same as Thread#reportonexception=true.

#25 Updated by Koichi Sasada 7 months ago

Sorry, it is not same, but we can consier that.

BTW, I think it true as default is good idea.

IMO, inter-thread communication via exception with Thread#join should be bad idea.

#26 Updated by Charles Nutter 7 months ago

ko1 (Koichi Sasada) wrote:

Sorry, it is not same, but we can consier that.

BTW, I think it true as default is good idea.

So to summarize:

  • Exceptions will log when they bubble out of a thread, as with -d, unless Thread#reportonexception == false
  • Thread#reportonexception defaults to true

Can we do this for 2.1?

IMO, inter-thread communication via exception with Thread#join should be bad idea.

+1

I had originally wanted something similar to Java, where you can set an "unhandled exception handler" for any thread. That would cover all cases, and the default case would be to just report the error. I was unsuccessful in specifying it because I wasn't sure how it should interact with abortonexception=.

#27 Updated by Hiroshi SHIBATA 3 months ago

  • Target version changed from 2.1.0 to current: 2.2.0

#28 Updated by Koichi Sasada 3 months ago

Restart for 2.2.
Matz, do you have any idea?

Also available in: Atom PDF