RSpec shorter backtrace output for test failures

Question

I'm using RSpec (latest Version, 2.12.2) to test a small Ruby class I'm working on. My problem is that when an RSpec test fails, the test output seems incredibly verbose, and shows a huge list of error messages, almost what seems to be a full backtrace. This means I have to scroll up to see the actual error message and the top of the trace.

I believe by default RSpec is supposed to do this but it doesn't seem to be doing it for me. For example, if I run rspec spec/my_spec.rb:132 (just run one test that's on L132), I get this output:

 Failure/Error: @f.has_changed?("test").should be_true
   expected: true value
        got: false
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-expectations-2.12.1/lib/rspec/expectations/fail_with.rb:33:in `fail_with'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-expectations-2.12.1/lib/rspec/expectations/handler.rb:33:in `handle_matcher'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-expectations-2.12.1/lib/rspec/expectations/syntax.rb:53:in `should'
 # /Users/JackFranklin/Dropbox/Sites/rubygems/filefixtures/spec/filefixtures_spec.rb:137:in `block (4 levels) in <top (required)>'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example.rb:114:in `instance_eval'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example.rb:114:in `block in run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example.rb:254:in `with_around_each_hooks'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example.rb:111:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:388:in `block in run_examples'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:384:in `map'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:384:in `run_examples'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:369:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `block in run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `map'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `block in run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `map'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/example_group.rb:370:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/command_line.rb:28:in `block (2 levels) in run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/command_line.rb:28:in `map'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/command_line.rb:28:in `block in run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/reporter.rb:34:in `report'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/command_line.rb:25:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/runner.rb:80:in `run'
 # /Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-core-2.12.2/lib/rspec/core/runner.rb:17:in `block in autorun'

Which, as you can see, is absolutely massive. I've not got any RSpec config files around that could be altering the configuration passed to RSpec.

Has anyone seen this before? I've tried Googling but searches have been fruitless.

Edit: I then set up config to make sure it was applying the default backtrace cleaning:

RSpec.configure do |config|
  # RSpec automatically cleans stuff out of backtraces;
  # sometimes this is annoying when trying to debug something e.g. a gem
  config.backtrace_clean_patterns = [
    /\/lib\d*\/ruby\//,
    /bin\//,
    /gems/,
    /spec\/spec_helper\.rb/,
    /lib\/rspec\/(core|expectations|matchers|mocks)/
  ]
end

But this doesn't make a difference. Looking at the output, it should be having most of it filtered out but it seems like the configuration isn't being applied?

Edit again:

In my config, I can even run cleaned_from_backtrace?(line) to see if a line should be cleaned. This returns true:

 config.cleaned_from_backtrace?("/Users/JackFranklin/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/rspec-expectations-2.12.1/lib/rspec/expectations/fail_with.rb:33:in `fail_with'")

But the actual output in the terminal remains the same!

Edit 3:

I am running RSpec with the command rspec, and nothing more. The project's .rspec file contains:

--color
--format progress

And there is no ~/.rspec file either that could be applying settings.

Answer 1

So after a bit more chatting with the RSpec folk on Github, I managed to hunt down the problem.

The problem was that by default, RSpec removes lines from the backtrace that match the Regex /gems/. I had my project within a folder with gems in the name: ~/Dropbox/rubygems/myproject, so every line of the backtrace was being removed, and when that happens, RSpec sensibly shows you the entire backtrace.

That explains the behaviour I was seeing.

It's always something silly like that. I hope if anyone else does this, perhaps this answer will save them some time.

Answer 2

Looks like you're running RSpec with -b, for a full backtrace. Normally, RSpec won't show its own internal backtrace like that, even when your test fails badly (i.e. throws an exception rather than just failing an assertion). If you're not explicitly running it with -b or --backtrace, check and make sure that you don't have that set in a .rspec config file, or that your IDE or whatever isn't passing it.

Answer 3

As Jim said, there's a -b or --backtrace option that will enable the full backtrace. Bear in mind that it's not just the .rspec file that could be triggering it; there's also ~/.rspec (for a developer's preferred options).

The other thing to bear in mind is that a formatter can spit out whatever portion of the backtrace that it wants. The formatters expose a simple way for any 3rd-party formatter to respect the backtrace-filtering configuration, but it you're using a 3rd-party formatter there is no guarantee it is using that properly. Are you using one of the built-in rspec formatters?

Finally, if it's not one of those things, I'm out of ideas. I'd have to have an example to play with to answer your question. Can you come up with a reproducible example (in a gist, hopefully)? I try to hang out in the rspec channel of irc.freenode.net regularly, so maybe you can catch me there and we can do some troubleshooting that way.

Answer 4

From version 3.4.0 / 2015-11-11 it is possible to filter backtrace by option:

RSpec.configure do |config|
   config.filter_rails_from_backtrace!
end