Skip to content
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

Include exception that raised failure in backtrace #2074

Merged
merged 1 commit into from
Oct 7, 2015
Merged

Include exception that raised failure in backtrace #2074

merged 1 commit into from
Oct 7, 2015

Conversation

mrageh
Copy link
Contributor

@mrageh mrageh commented Sep 28, 2015

Problem

Sometimes rspec-core does not display the underlying cause of an
exception that was raised.

Previously if an exception was raised there would sometimes be an
underlying cause of the exception. For example an exception that's
raised and rescued within an application causes the exception that
is displayed in the stacktrace.

class BrokenCode
  def self.shallow_method
    begin
      deep_method
    rescue
      raise "Something happened and I'm hiding that from the message
'because usability'."
    end
  end

  def self.deep_method
    raise 'The real cause for the failure is here!'
  end
end

RSpec.describe 'some broken code' do
  it 'works' do
    BrokenCode.shallow_method
  end
end
  1) some broken code works
     Failure/Error: raise "Something happened and I'm hiding that from
the message 'because usability'."
     RuntimeError:
       Something happened and I'm hiding that from the message 'because
usability'.
     # ./my_spec.rb:32:in `rescue in shallow_method'
     # ./my_spec.rb:29:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'

The above example demonstrates the problem, the stacktrace above is not
very clear as it does not show the initial exception that caused the
problem. This makes it difficult to fix their failing test.

Solution

Ruby 2.1 introduced Exception#cause which shows the underlying cause
of an exception if there is one. This commit uses that new Ruby method
to get the cause of an exception and display it in the stacktrace.

The stacktrace for the above code example would change to the below
example:

  1) some broken code works
     Failure/Error: raise "Something happened and I'm hiding that from
the message 'because usability'."
     RuntimeError:
       Something happened and I'm hiding that from the message 'because
usability'.
     # ./my_spec.rb:32:in `rescue in shallow_method'
     # ./my_spec.rb:29:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'
  ------------------
  --- Caused by: ---
     RuntimeError:
       The real cause for the failure is here!
     # ./my_spec.rb:37:in `deep_method'
     # ./my_spec.rb:30:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'

This makes it a lot easier to fix the main cause of the test failure.

Edge case

There may be a situation where lots of exceptions are captured and
bubble up the stacktrace. In that case I don't think we want to print out
the cause of every single exception. Instead what I propose we do is to
print out the first exception that caused the other exceptions to bubble
up the stack trace.

This may be a potential fix for #2044


unless potential_lines.empty?
lines += potential_lines.last
end
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you're going to only take the last cause, why bother generating the string for all of them? It would seem better to loop over the causes until you've found the last, then do the string generation and add the last line directly to lines.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point, I'll update the pr to do the string generation for the last cause only 👍

@JonRowe
Copy link
Member

JonRowe commented Sep 28, 2015

Great start, I have some feedback from a mostly style point of view, but the rubocop build is also failing so thats needs addressing, let me know if you need any help.

@mrageh
Copy link
Contributor Author

mrageh commented Sep 29, 2015

@JonRowe Thanks for the feedback, I'll update this pr tonight with your suggestsions and fix the failing build

@fables-tales
Copy link
Member

This all looks good, I have nothing to add on top of what Jon said. Let us know if you need any further help :)

@mrageh
Copy link
Contributor Author

mrageh commented Sep 30, 2015

@JonRowe I've addressed a few of the issues you mentioned but my solution still needs some refactoring and I need to get the build passing. I'll review this tomorrow and see if I can get this finished off

@mrageh
Copy link
Contributor Author

mrageh commented Oct 1, 2015

@samphippen The build is broken and I don't fully understand why, can you please point me in the right direction so I can figure out what the problem is?

@JonRowe suggested I pin the rspec-support repo in the Gemfile to this branch rspec/rspec-support#240. After doing that I used this new method RSpec::Support::Ruby.supports_exception_cause?and the test suite passed locally. But when the build runs on Travis that method is undefined. So I did a bit of investigation and it turns out that my local machine uses the correct rspec-support branch whereas the one on Travis does'nt. When Travis runs it uses script/run_build which execute the function defined below:

https://github.com/rspec/rspec-core/blob/master/script/run_build#L28
https://github.com/rspec/rspec-core/blob/master/script/functions.sh#L79

These are the builds that fail and below them I've printed out the part that shows which rspec-support version it's using.

1.8.7 https://travis-ci.org/rspec/rspec-core/jobs/83143375 *
1.9.2 https://travis-ci.org/rspec/rspec-core/jobs/83143377 *
1.9.3 https://travis-ci.org/rspec/rspec-core/jobs/83143379 *
2.0.0 https://travis-ci.org/rspec/rspec-core/jobs/83143380 *
ree https://travis-ci.org/rspec/rspec-core/jobs/83143385 *

 Running specs for rspec-expectations
~/build/rspec/rspec-expectations ~/build/rspec/rspec-core
Fetching gem metadata from https://rubygems.org/..........
Fetching additional metadata from https://rubygems.org/..
Resolving dependencies...
Using rspec-support 3.4.0.pre from source at /home/travis/build/rspec/rspec-support

/home/travis/build/rspec/rspec-core/lib/rspec/core/formatters/exception_presenter.rb:43: undefined method supports_exception_cause?' for RSpec::Support::RubyFeatures:Module (NoMethodError)

Below is the rspec-support gem that my local machine uses:

Using rspec-support 3.4.0.pre from git://github.com/rspec/rspec-support.git (at exception_cause_supported)

@myronmarston
Copy link
Member

@mrageh -- the problem you are running into is described in rspec/rspec-dev#137. We're going to have to fix our merge the rspec-support PR or change our build scripts to fix it. For now don't worry about it.

@myronmarston
Copy link
Member

@mrageh -- I just merged rspec/rspec-support#240. You should be able to remove your temporary pin to the rspec-support branch and the build should work now. (Please force push so the temporary pin isn't in our history).

@mrageh
Copy link
Contributor Author

mrageh commented Oct 1, 2015

thank you @myronmarston

@mrageh
Copy link
Contributor Author

mrageh commented Oct 1, 2015

@myronmarston I've forced pushed and the commit containing temporary pin is no longer in my branch. However the build is still failing on Ruby 2.2 and 2.1 and on Ruby 2.1 the failure makes little sense to me
https://travis-ci.org/rspec/rspec-core/jobs/83153115

def formatted_cause(exception)
exceptions = []

while exception.respond_to?(:cause) && exception.cause
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is the respond_to? check here necessary? Under what conditions would Exception.method_defined?(:cause) return true (that's the logic for the supports_exception_cause? check) and exception.respond_to?(:cause) return false?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few of the tests within describe '#fully_formatted' in https://github.com/rspec/rspec-core/blob/master/spec/rspec/core/formatters/exception_presenter_spec.rb fail because instance_double received an unexpected message :cause. So in order to side step this issue and keep the diff small I decided to use exception.respond_to?(:cause). That way I would not need to add a before block stubbing out the method or stub it out in each particular instance.

However now that I've finished the initial implementation and this pr has been reviewed I think it's good that I stub this method out in each instance_double, what would you do in this case?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, I think I'd favor not using test doubles for this case. Exceptions aren't hard or expensive to create, and we're not designing the exception API, so I don't see much benefit to using test doubles for the exceptions here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should I change all the existing exception test doubles to actual Exceptions?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's not necessary but if you want to - go for it! I'd just ask that you do that in a separate commit.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are seven failing tests and that's cause they are test doubles of the Exception class, so I need to either stub the method or I could just use actual instances of the Exception class. Since we both prefer not using doubles in this case, I think it's best I just change the failing tests to use real objects.

I'll do it in a separate commit thanks for the swift response

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I spent sometime trying to change the three exception test doubles to actual instances of exception. but that would mean I still have to stub the cause, message and backtrace for a lot of the tests in a before block. @myronmarston do you think I should still use real instances of exception?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If you use a real exception, please do not stub anything on it. Instead, you can set the exception by passing it as an argument to Exception.new. You can set the backtrace by calling exception.set_backtrace. You can set the cause by simulating the conditions where ruby sets the cause:

irb(main):023:0> ex = begin
irb(main):024:1*   begin
irb(main):025:2*     raise "root cause"
irb(main):026:2>   rescue
irb(main):027:2>     raise "from rescue"
irb(main):028:2>   end
irb(main):029:1> rescue => e
irb(main):030:1>   e
irb(main):031:1> end
=> #<RuntimeError: from rescue>
irb(main):032:0> ex.cause
=> #<RuntimeError: root cause>

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you I think I prefer using test_doubles of the Exception class in this case as I think that looks nicer, that's only if you have no objections to me doing that 👍

@myronmarston
Copy link
Member

There are two things at work causing the build failures:

  • We enforce that no Ruby warnings are generated by either our lib code or our specs. Unfortunately, ruby 2.2 generates an annoying warning when you have a local variable at one part of the file, and later in the file you use bare-word syntax to call a method on self with no arguments. They've removed this warning from ruby but it's still there in the patch level of 2.2 that travis runs, unfortunately. Specifically, the problem is that presenter is declared as a local variable on line 52 and then, later in the file you call the presenter method on line 136 (let(:presenter) at the top of the file simply defines a presenter method). As you can see, the ruby warning is super annoying and not helpful to RSpec users, given the usage of let. The fix is either to rename the presenter local variable on line 52 (maybe to the_presenter or something... - but don't forget to update the references in that spec!) or to make your call to presenter on line 136 an explicit method call by doing self.presenter or presenter(). Personally, I think I'd prefer the former as this problem could pop up again in the future due to the fact that we have the let(:presenter) and the local variable presenter in the one spec. If you run the spec suite on an early patch level o ruby 2.2 you should be able to see the failure from this and then see the failure go away when you fix it.
  • As of Update coverage #1905 we enforce that rspec-core has 100% test coverage on ruby 2.1 and above. This has helped identify dead code and some bugs. It's failing now on 2.1 (and would be failing on 2.2 if not for the warning mentioned above) because this line is uncovered on ruby 2.1 and above -- and in fact it can never be covered, because that method def is only defined on ruby versions that lack Exception.cause. The solution is to add # :nocov: comments before and after the method definition within the else. That's what we do everywhere we define an alternate implementation of a method for an older version of ruby. To see this locally, you'll need to run script/rspec_with_simplecov. That's a special binary we have to use to use simplecov with RSpec on itself because simplecov has to be loaded before all the code you are intending to check coverage of -- which means that the normal rspec command won't work because RSpec loads itself first.

Thanks for following through on this. Our build can be a bit fidly but helps ensure consistency and better code quality.

@mrageh
Copy link
Contributor Author

mrageh commented Oct 1, 2015

@myronmarston thank you :)

@mrageh
Copy link
Contributor Author

mrageh commented Oct 3, 2015

@myronmarston I've kind of finished the PR, you can see the changes I introduced to fix the failing build in the last commit....

@mrageh
Copy link
Contributor Author

mrageh commented Oct 5, 2015

What are the next steps for this pull request?
cc @myronmarston, @JonRowe and @samphippen

@fables-tales
Copy link
Member

this LGTM, @JonRowe @myronmarston. This good to merge?

@JonRowe
Copy link
Member

JonRowe commented Oct 5, 2015

Needs to be squashed first please

lines = backtrace_formatter.format_backtrace((exception.backtrace || []), example.metadata)
potential_lines = formatted_cause(exception)

lines += potential_lines unless potential_lines.empty?
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[a+b+c] + [] is [a+b+c] so it really doesn't matter if its empty

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

@mrageh
Copy link
Contributor Author

mrageh commented Oct 5, 2015

@JonRowe thanks for the review. I've changed my solution a bit and I like this approach better, instead of using a while loop I've added a simple method that's called recursively. This simplifies things a bit, would you agree?

def formatted_backtrace(exception=@exception)
lines = backtrace_formatter.format_backtrace((exception.backtrace || []), example.metadata)

lines + formatted_cause(exception)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it makes sense to collapse these lines and just break it up over two lines. e.g.

backtrace_formatter.format_backtrace((exception.backtrace || []), example.metadata) +
  formatted_cause(exception)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done 👍

@mrageh
Copy link
Contributor Author

mrageh commented Oct 6, 2015

@JonRowe After applying the changes you suggested the build has started failing and the failure messages do not contain descriptive error messages.

@myronmarston
Copy link
Member

The build is currently failing due to some recent changes @JonRowe made to our license file in master. Reasonably, he pushed to master expecting it to not have an affect on the build but it actually does (due to YARD/gemspec references to the license file and whitespace issues). He's got a PR out to fix the issues and I expect it to be fixed later today. You'll have to rebase after those get merged and then your PR should (hopefully) go green. Sorry about the failures noise!

@JonRowe
Copy link
Member

JonRowe commented Oct 7, 2015

The build should be fixed now, so if you rebase (and squash please!) you should find that this passes

@mrageh
Copy link
Contributor Author

mrageh commented Oct 7, 2015

No problem @myronmarston
Thanks @JonRowe

@mrageh
Copy link
Contributor Author

mrageh commented Oct 7, 2015

@myronmarston and @JonRowe you've both been really helpful and I enjoyed working on this issue. This is my first time contributing to rspec and I've got some questions/feedback that may make it easier for new comers to contribute to this project. If you're interested in hearing my feedback please let me know

Problem

Sometimes rspec-core does not display the underlying cause of an
exception that was raised.

Previously if an exception was raised there would sometimes be an
underlying cause of the exception. For example an exception that's
raised and rescued within an application causes the exception that
is displayed in the stacktrace.

```
class BrokenCode
  def self.shallow_method
    begin
      deep_method
    rescue
      raise "Something happened and I'm hiding that from the message
'because usability'."
    end
  end

  def self.deep_method
    raise 'The real cause for the failure is here!'
  end
end

RSpec.describe 'some broken code' do
  it 'works' do
    BrokenCode.shallow_method
  end
end
```

```
  1) some broken code works
     Failure/Error: raise "Something happened and I'm hiding that from
the message 'because usability'."
     RuntimeError:
       Something happened and I'm hiding that from the message 'because
usability'.
     # ./my_spec.rb:32:in `rescue in shallow_method'
     # ./my_spec.rb:29:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'
```

The above example demonstrates the problem, the stacktrace above is not
very clear as it does not show the initial exception that caused the
problem. This makes it difficult to fix their failing test.

Solution

Ruby 2.1 introduced `Exception#cause` which shows the underlying cause
of an exception if there is one. This commit uses that new Ruby method
to get the cause of an exception and display it in the stacktrace.

The stacktrace for the above code example would change to the below
example:

```
  1) some broken code works
     Failure/Error: raise "Something happened and I'm hiding that from
the message 'because usability'."
     RuntimeError:
       Something happened and I'm hiding that from the message 'because
usability'.
     # ./my_spec.rb:32:in `rescue in shallow_method'
     # ./my_spec.rb:29:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'
  ------------------
  --- Caused by: ---
     RuntimeError:
       The real cause for the failure is here!
     # ./my_spec.rb:37:in `deep_method'
     # ./my_spec.rb:30:in `shallow_method'
     # ./my_spec.rb:43:in `block (2 levels) in <top (required)>'
```

This makes it a lot easier to fix the main cause of the test failure.

Edge case

There may be a situation where lots of exceptions are captured and
bubble up the stacktrace. In that case I don't think we want to print out
the cause of every single exception. Instead what I propose we do is to
print out the first exception that caused the other exceptions to bubble
up the stack trace.
@myronmarston
Copy link
Member

Yes, we're always interested in feedback in how to make the contributing process smoother. You can either write it here or email it to us directly if you prefer. You can get our email addresses from our git commits:

git log --author myron | grep Author | sed -n 1p
git log --author jon | grep Author | sed -n 1p

@myronmarston
Copy link
Member

This LGTM to me now. Thanks for the hard work, @mrageh!

myronmarston added a commit that referenced this pull request Oct 7, 2015
…-stacktrace-in-exception-backtrace

Include exception that raised failure in backtrace
@myronmarston myronmarston merged commit 33e16ba into rspec:master Oct 7, 2015
myronmarston added a commit that referenced this pull request Oct 7, 2015
myronmarston added a commit that referenced this pull request Nov 18, 2015
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with #2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.
myronmarston added a commit that referenced this pull request Nov 18, 2015
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with #2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.

Fixes #2117.
myronmarston added a commit that referenced this pull request Nov 19, 2015
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with #2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.

Fixes #2117.
myrridin pushed a commit to myrridin/rspec-core that referenced this pull request Dec 11, 2015
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with rspec#2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.

Fixes rspec#2117.
MatheusRich pushed a commit to MatheusRich/rspec-core that referenced this pull request Oct 30, 2020
…aused-stacktrace-in-exception-backtrace

Include exception that raised failure in backtrace
MatheusRich pushed a commit to MatheusRich/rspec-core that referenced this pull request Oct 30, 2020
MatheusRich pushed a commit to MatheusRich/rspec-core that referenced this pull request Oct 30, 2020
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with rspec#2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.

Fixes rspec#2117.
yujinakayama pushed a commit to yujinakayama/rspec-monorepo that referenced this pull request Oct 6, 2021
`Exception.new.backtrace` is `nil` so we can't count on
there always being a backtrace. Before now we relied
on the `format_backtrace` caller handling this (passing
`ex.backtrace || []`), but with rspec/rspec-core#2074 now also including
the `exception.cause` in failure output, the code there
did not guard the `format_backtrace` call with `|| []`
and is causing users to get a `NoMethodError`. It's
easiest if `format_backtrace just handles the `nil` case
so each caller does not have to remember to handle it.

Fixes rspec/rspec-core#2117.

---
This commit was imported from rspec/rspec-core@92c95d5.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants