New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exception backtrace is nil when it should be present #4467

Closed
DavidEGrayson opened this Issue Jan 31, 2017 · 11 comments

Comments

Projects
None yet
3 participants
@DavidEGrayson
Contributor

DavidEGrayson commented Jan 31, 2017

It looks like the performance improvements mentioned on the JRuby blog probably broke exception backtrace generation in some cases. This affected RSpec, causing the following bug: rspec/rspec-core#2299. I can reproduce the problem by running this very simple script in JRuby:

begin
  raise
rescue ArgumentError
rescue StandardError => e
  if e.backtrace.nil?
    puts "Rescued an exception with no backtrace!"
  else
    puts "Looks good"
  end
end

Here is a shell session showing my environment and the output of that script:

$ jruby -v
jruby 9.1.7.0 (2.3.1) 2017-01-11 68056ae Java HotSpot(TM) 64-Bit Server VM 25.121-b13 on 1.8.0_121-b13 +jit [mswin32-x86_64]
$ uname -a
MINGW64_NT-10.0 URANIUM 2.6.0(0.304/5/3) 2016-09-07 20:45 x86_64 Msys
$ jruby simple.rb
Rescued an exception with no backtrace!

MRI behaves as expected and prints "Looks good" when it runs that same script.

For anyone affected by this, a workaround is to add => _ to the first rescue statement.

DavidEGrayson added a commit to DavidEGrayson/rspec-core that referenced this issue Jan 31, 2017

Fix exception backtraces on JRuby.
This is a workaround for a JRuby bug:
jruby/jruby#4467

DavidEGrayson added a commit to DavidEGrayson/rspec-core that referenced this issue Jan 31, 2017

Fix exception backtraces on JRuby. Fixes #2299.
This is a workaround for a JRuby bug:
jruby/jruby#4467

@headius headius added this to the JRuby 9.1.8.0 milestone Jan 31, 2017

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 31, 2017

Member

Ok this is pretty easy to understand where we tripped up I think:

begin
  p 1
rescue Foo
rescue Bar
end

AST:

AST:
RootNode 0
  BeginNode 0
    RescueNode 1
      RescueBodyNode 2
        ArrayNode 3
          ConstNode:Foo 3
, 
        RescueBodyNode 3
          ArrayNode 4
            ConstNode:Bar 4
      FCallNode:p 1
        ArrayNode 1
          FixnumNode 1
, null
, null

The RescueBodyNodes are nested and the first one says we don't need the backtrace. Our builder needs to be made a little smarter to see multiple rescue bodies for this case...

Member

enebo commented Jan 31, 2017

Ok this is pretty easy to understand where we tripped up I think:

begin
  p 1
rescue Foo
rescue Bar
end

AST:

AST:
RootNode 0
  BeginNode 0
    RescueNode 1
      RescueBodyNode 2
        ArrayNode 3
          ConstNode:Foo 3
, 
        RescueBodyNode 3
          ArrayNode 4
            ConstNode:Bar 4
      FCallNode:p 1
        ArrayNode 1
          FixnumNode 1
, null
, null

The RescueBodyNodes are nested and the first one says we don't need the backtrace. Our builder needs to be made a little smarter to see multiple rescue bodies for this case...

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 31, 2017

Member

@DavidEGrayson A workaround for now would be to not have the empty case as the first rescue. I will fix this tomorrow and it will be in 9.1.8.0 but if you swap order then it will work with earlier versions of JRuby too.

Member

enebo commented Jan 31, 2017

@DavidEGrayson A workaround for now would be to not have the empty case as the first rescue. I will fix this tomorrow and it will be in 9.1.8.0 but if you swap order then it will work with earlier versions of JRuby too.

@DavidEGrayson

This comment has been minimized.

Show comment
Hide comment
@DavidEGrayson

DavidEGrayson Jan 31, 2017

Contributor

Thanks for looking at this so quickly! Swapping the order of rescues is not a general workaround because it can change the behavior of the program, but I thought my workaround of adding => _ is good enough for now.

Contributor

DavidEGrayson commented Jan 31, 2017

Thanks for looking at this so quickly! Swapping the order of rescues is not a general workaround because it can change the behavior of the program, but I thought my workaround of adding => _ is good enough for now.

@DavidEGrayson

This comment has been minimized.

Show comment
Hide comment
@DavidEGrayson

DavidEGrayson Feb 1, 2017

Contributor

I think it will be pretty hard to correctly predict whether backtraces are needed ahead of time, before the exception is thrown. Here is a program with a normal-looking rescue block but you don't know what class StandardError will resolve to ahead of time. The exception needs a backtrace if and only if the environment variable PATHOLOGICAL is set to Y:

module M
  begin
    if ENV['PATHOLOGICAL'] == 'Y'
      class StandardError < ::StandardError
      end
    end
    raise 'hello'
  rescue StandardError
  end
end

It seems like the only rescue blocks that are easy to reason about correctly before you run them are the ones that don't specify a class.

Contributor

DavidEGrayson commented Feb 1, 2017

I think it will be pretty hard to correctly predict whether backtraces are needed ahead of time, before the exception is thrown. Here is a program with a normal-looking rescue block but you don't know what class StandardError will resolve to ahead of time. The exception needs a backtrace if and only if the environment variable PATHOLOGICAL is set to Y:

module M
  begin
    if ENV['PATHOLOGICAL'] == 'Y'
      class StandardError < ::StandardError
      end
    end
    raise 'hello'
  rescue StandardError
  end
end

It seems like the only rescue blocks that are easy to reason about correctly before you run them are the ones that don't specify a class.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Feb 1, 2017

Member

@DavidEGrayson just so I understand you are you saying that the === operator of a derived class would end up asking for the backtrace? I am increasingly thinking we should just use this for RESCUE_MOD cases like 'foo rescue nil' but my mind is not catching what you are saying.

Member

enebo commented Feb 1, 2017

@DavidEGrayson just so I understand you are you saying that the === operator of a derived class would end up asking for the backtrace? I am increasingly thinking we should just use this for RESCUE_MOD cases like 'foo rescue nil' but my mind is not catching what you are saying.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 1, 2017

Member

I believe we are willing to break some pathological cases -- like a rescue with a === impl that inspects the backtrace (why?) -- in order to reduce the tremendous cost of generating stack traces when they actually aren't needed.

Generally the only time you will miss the trace is if the error gets reported (as in your case with rspec failures), and I believe there's a flag to disable this behavior (or if my memory is wrong, it would be easy to add). The alternative -- disabling this feature which has only had a couple easily-fixed issues -- would mean that libraries that raise exceptions for flow control (not uncommon) run something like 1000x slower for those cases.

The fix for this case is simple and obvious: we need to examine all rescues to see if they're nontrivial. Given that fix, your original issue should be resolved. If a time comes when someone really wants === to have access to the backtrace and then do almost nothing in the rescue body, we'll deal with it then.

Member

headius commented Feb 1, 2017

I believe we are willing to break some pathological cases -- like a rescue with a === impl that inspects the backtrace (why?) -- in order to reduce the tremendous cost of generating stack traces when they actually aren't needed.

Generally the only time you will miss the trace is if the error gets reported (as in your case with rspec failures), and I believe there's a flag to disable this behavior (or if my memory is wrong, it would be easy to add). The alternative -- disabling this feature which has only had a couple easily-fixed issues -- would mean that libraries that raise exceptions for flow control (not uncommon) run something like 1000x slower for those cases.

The fix for this case is simple and obvious: we need to examine all rescues to see if they're nontrivial. Given that fix, your original issue should be resolved. If a time comes when someone really wants === to have access to the backtrace and then do almost nothing in the rescue body, we'll deal with it then.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 1, 2017

Member

FWIW, I can think of one thing that would make the pathological cases pretty benign: instead of no trace at all, we provide a dummy trace that suggests the flag to disable backtrace suppression and links to a wiki information page with explanations and workarounds.

Member

headius commented Feb 1, 2017

FWIW, I can think of one thing that would make the pathological cases pretty benign: instead of no trace at all, we provide a dummy trace that suggests the flag to disable backtrace suppression and links to a wiki information page with explanations and workarounds.

@DavidEGrayson

This comment has been minimized.

Show comment
Hide comment
@DavidEGrayson

DavidEGrayson Feb 1, 2017

Contributor

I wasn't trying to talk about derived classes or the === operator, the point was that often you will not know what kind of exception is being caught by the rescue clause ahead of time. In the normal case above, rescue StandardError rescues all exceptions of type ::StandardError so we can skip backtraces for most types of exceptions. In the pathological example above, rescue StandardError only rescues exceptions of type M::StandardError (which could be whatever we want it to be), so most typical exceptions will not be caught, and we need to see stack traces for them.

I believe we are willing to break some pathological cases

I thought you would say that. If you can fix RSpec, that would be great. However, after the fix, if there are still some cases where you are sacrificing correctness for speed then I will probably point it out.

Contributor

DavidEGrayson commented Feb 1, 2017

I wasn't trying to talk about derived classes or the === operator, the point was that often you will not know what kind of exception is being caught by the rescue clause ahead of time. In the normal case above, rescue StandardError rescues all exceptions of type ::StandardError so we can skip backtraces for most types of exceptions. In the pathological example above, rescue StandardError only rescues exceptions of type M::StandardError (which could be whatever we want it to be), so most typical exceptions will not be caught, and we need to see stack traces for them.

I believe we are willing to break some pathological cases

I thought you would say that. If you can fix RSpec, that would be great. However, after the fix, if there are still some cases where you are sacrificing correctness for speed then I will probably point it out.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Feb 1, 2017

Member

Ahh, I understand what you mean now. The best option for dealing would be as @enebo hinted at: only do this optimization when there's a bare rescue or "rescue nil" style modifier (since those are always predictably StandardError). I believe we only omit the backtrace for StandardError subclasses now anyway, but we may want to turn off the optimization when we can't prove all StandardError are rescued.

Member

headius commented Feb 1, 2017

Ahh, I understand what you mean now. The best option for dealing would be as @enebo hinted at: only do this optimization when there's a bare rescue or "rescue nil" style modifier (since those are always predictably StandardError). I believe we only omit the backtrace for StandardError subclasses now anyway, but we may want to turn off the optimization when we can't prove all StandardError are rescued.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Feb 1, 2017

Member

@DavidEGrayson aha..I get it now. yeah RESCUE_MOD case only now. Which was the original intent of the optimization but I got greedy.

Member

enebo commented Feb 1, 2017

@DavidEGrayson aha..I get it now. yeah RESCUE_MOD case only now. Which was the original intent of the optimization but I got greedy.

@enebo enebo closed this in 948554d Feb 10, 2017

@DavidEGrayson

This comment has been minimized.

Show comment
Hide comment
@DavidEGrayson

DavidEGrayson Feb 10, 2017

Contributor

Thanks!

Contributor

DavidEGrayson commented Feb 10, 2017

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment