Feature #6647

Exceptions raised in threads should be logged

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

[ruby-core:45864]
Status:Assigned
Priority:Normal
Assignee:Yukihiro Matsumoto

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.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}"}
end
end
end
end

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

END

Output:

system ~/projects/jruby $ ruby thread_error.rb
Thread for block #Proc:0x000000010d008a80@thread_error.rb:17 terminated with exception: divided by 0
thread_error.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'
thread_error.rb:5:in old_new'
thread_error.rb:5:in
new'
thread_error.rb:17
After thread

History

#1 Updated by Charles Nutter about 3 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 about 3 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 .abort_on_exception 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 .abort_on_exception defaulted to true? This would seem to be the behaviour to suit most users.

#3 Updated by Alex Young about 3 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 .abort_on_exception 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 .abort_on_exception 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.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}"}
end
end
end
end

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

END

Output:

system ~/projects/jruby $ ruby thread_error.rb
Thread for block #Proc:0x000000010d008a80@thread_error.rb:17 terminated with exception: divided by 0
thread_error.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'
thread_error.rb:5:in old_new'
thread_error.rb:5:in
new'
thread_error.rb:17
After thread

#4 Updated by Eric Wong about 3 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 .abort_on_exception 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 about 3 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 .abort_on_exception 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 3 years ago

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

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#abort_on_exception = false)
  • Writing to STDERR could cause problem with existing applications so we should take care about it.
  • rb_warn() instead of puts would be good because we already using rb_warns.

Matz, do you mind if we dump Thread error with rb_warn if Thread#abort_on_exception = false?

#7 Updated by Charles Nutter almost 3 years ago

Any update on this?

#8 Updated by Charles Nutter over 2 years ago

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

#9 Updated by Motohiro KOSAKI over 2 years 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 2 years 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.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}"}
end
end
end
end

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

END

Output:

system ~/projects/jruby $ ruby thread_error.rb
Thread for block #Proc:0x000000010d008a80@thread_error.rb:17 terminated with exception: divided by 0
thread_error.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'
thread_error.rb:5:in old_new'
thread_error.rb:5:in
new'
thread_error.rb:17
After thread

#11 Updated by Charles Nutter over 2 years ago

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

  • How does abort_on_exception= interact with a callback system? ** I tried implementing abort_on_exception=true to use a builtin callback that raises in Thread.main, but should abort_on_exception=true blow away a previously-set callback? ** Similarly: should abort_on_exception=false reset to a do-nothing callback? ** If neither of these, how do we combine callback and abort_on_exception behavior?
  • Seems like there should be a Thread.default_exception_handler 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 2 years ago

Ping!

#13 Updated by Charles Nutter over 2 years 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 2 years 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 2 years ago

  • Target version changed from 2.0.0 to next minor

#16 Updated by Charles Nutter almost 2 years 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 almost 2 years 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.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}"}
end
end
end
end

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

END

Output:

system ~/projects/jruby $ ruby thread_error.rb
Thread for block #Proc:0x000000010d008a80@thread_error.rb:17 terminated
with exception: divided by 0
thread_error.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'
thread_error.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 almost 2 years ago

  • Target version changed from next minor to 2.1.0

#19 Updated by Koichi Sasada almost 2 years 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 almost 2 years 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 almost 2 years ago

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

#22 Updated by Akira Tanaka almost 2 years 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 almost 2 years 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 report_on_exception=(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#report_on_exception = 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 almost 2 years ago

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

#25 Updated by Koichi Sasada almost 2 years 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 almost 2 years 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#report_on_exception == false
  • Thread#report_on_exception 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 abort_on_exception=.

#27 Updated by Hiroshi SHIBATA over 1 year ago

  • Target version changed from 2.1.0 to current: 2.2.0

#28 Updated by Koichi Sasada over 1 year ago

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

#29 Updated by Lin Jen-Shin about 2 months ago

Not sure if a +1 would do anything, but I like the idea of
Thread#report_on_exception defaults to true.

For quick and one time scripts, it's tedious to write
Thread.current.abort_on_exception = true all the time,
and it shouldn't be set to true by default, either.
So at least make debugging easier by default is a good idea,
and who doesn't like to see warnings anyway? :P

I was referred from yahns mailing list:
http://yhbt.net/yahns-public/m/20150508170311.GA1260%40dcvr.yhbt.net.html
Which some worker threads were dead silently and it's puzzling
if I don't even know there's an exception was raised.

#30 Updated by Eric Wong about 2 months ago

I have an actual patch which is only 2 lines, but there's some test
failures and MANY warnings I don't feel motivated to fix just yet
unless matz approves the feature:

http://80x24.org/spew/m/0a12f5c2abd2dfc2f055922a16d02019ee707397.txt

#31 Updated by Charles Nutter about 2 months ago

Eric Wong wrote:

I have an actual patch which is only 2 lines, but there's some test
failures and MANY warnings I don't feel motivated to fix just yet
unless matz approves the feature:

Hot diggity! I bet there's several of these that indicate bugs to be fixed. At the very least, they indicate exceptions that are being raised and not dealt with.

I think this is great evidence that this IS the right change to make.

Also available in: Atom PDF