RSpec always showing backtrace

[jackfranklin]

I posted a Question on Stackoverflow last night about RSpec always showing me a backtrace. Both answers had good suggestion but none of them worked - leading me to think I might have stumbled upon a bug of some sort?

Essentially, RSpec is always showing the full backtrace, even when I don't tell it to or explicitly configure it not to. Here's my spec_helper.rb file:

# See http://rubydoc.info/gems/rspec-core/RSpec/Core/Configuration
RSpec.configure do |config|
  config.treat_symbols_as_metadata_keys_with_true_values = true
  config.run_all_when_everything_filtered = true
  config.filter_run :focus
  config.full_backtrace=false
  config.order = 'random'
end

And here's my test_spec.rb file:

require_relative "../test"
describe Foo do
  it "adds numbers" do
    Foo.add(2, 2).should == 4
  end
end

The test.rb file simply sets up Foo.add and makes it always return "3", so the above test fails. When it does fail however, I get a massive backtrace. I run the tests just with rspec, no extra configuration passed in.

Because the output for this is massive, rather than put it in here I've created a Gist showing the output when the test fails. As you can see, it's showing the entire backtrace.

I do have .rspec file but it only contains:

--color
--format progress

And there is not a global ~/.rspec file either.

rspec -v gives me Version 2.12.2 and I am running Ruby 1.9.3p327.

I am at a loss at to what is happening here unfortunately - I have a horrible feeling I'm doing something silly but I can't spot it if I am.

Thanks,

Jack.

[myronmarston]

I don't have any ideas for what the problem is. Backtrace filtering is certainly working for me, and I haven't heard of problems from any other users (if it was a widespread problem I'm sure we would get many reports). Someone will have to troubleshoot the code in rspec-core (running in the context of your spec suite) that should be filtering the backtraces and figure out why it's not. If you can come up with something I can clone and run to demo the problem (such as a gist), I'll be happy to take a look; if not, you'll have to do that yourself. If you decide to troubleshoot this, I recommend putting a breakpoint and/or some logging in this method--that's where the backtrace should be filtered.

[jackfranklin]

@myronmarston thanks for your help. I've just pushed my code to a repository on Github, if that helps you debug it: https://github.com/jackfranklin/rspec-troubleshooting

Thanks again,

Jack

[myronmarston]

I hate to say "it works for me"....but it in fact does:

➜  rspec-troubleshooting git:(master) ruby --version
ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-darwin11.4.0]
➜  rspec-troubleshooting git:(master) rspec --version
2.12.2
➜  rspec-troubleshooting git:(master) rspec
F

Failures:

  1) Foo adds numbers
     Failure/Error: Foo.add(2, 2).should == 4
       expected: 4
            got: 3 (using ==)
     # ./spec/test_spec.rb:5:in `block (2 levels) in <top (required)>'

Finished in 0.00046 seconds
1 example, 1 failure

Failed examples:

rspec ./spec/test_spec.rb:4 # Foo adds numbers

There's something different on your box. Not to beat a dead horse or anything, but are you absolutely sure you don't have a .rspec file in your home directory with --backtrace in it? That's the only thing I can think of that would cause this.

[alindeman]

Do you have anything in the SPEC_OPTS environment variable?

$ echo $SPEC_OPTS

[jackfranklin]

@alindeman nope:

Sites/rubygems/rspectest (master|✚1)
→ echo $SPEC_OPTS

Sites/rubygems/rspectest (master|✚1)
→ cat ~/.rspec
cat: /Users/JackFranklin/.rspec: No such file or directory
Sites/rubygems/rspectest (master|✚1)
→ cat .rspec
--color
--format progress

@myronmarston I've absolutely no idea. Also to add - I've tried this on two Macbooks, my work one and my personal one...which seems to rule out it being something specific to one machine.

I don't suppose it could be something within rbenv causing the issue? It seems unlikely given I've never had any issues with gems caused by rbenv before.

Thank you for your help so far - much appreciated.

[myronmarston]

@jackfranklin -- can you start debugging the issue on your own by instrumenting the method I linked to above with puts or debugger statements? You shouldn't fear editing installed gems for troubleshooting purposes...I do it frequently :).

[jackfranklin]

@myronmarston is there a good guide on how to do that? Diving into installed Gems is something I'm new to! :)

Edit - cancel that. Found it and now doing some debugging. Will report back.

[jackfranklin]

The first thing I did was make sure it was getting past the two early returns.

puts "BACKTRACE CALLED"
puts "full_backtrace option true? #{options[:full_backtrace] == true }"                                                                          
return "" unless backtrace
return backtrace if options[:full_backtrace] == true
puts "PAST CONDITIONAL RETURNS"

And it does indeed get to there. So it's not a problem with the options config being incorrectly set or anything.

[jackfranklin]

I found the issue:

puts "JUST BEFORE cleansed"
cleansed = backtrace.map { |line| backtrace_line(line) }.compact
puts "cleansed: #{cleansed}"  

The output is:

JUST BEFORE cleansed
cleansed: []

Which is why it returns the full backtrace, as cleansed is empty. I'll do some more digging.

edit

The one line that shouldn't get cleaned from the backtrace is this one:

/Users/JackFranklin/Dropbox/Sites/rubygems/rspectest/spec/test_spec.rb:5:in `block (2 levels) in <top (required)>'

So in the backtrace_line method I put in:

puts "called on #{line}"
puts "cleaned_from_backtrace? #{RSpec.configuration.cleaned_from_backtrace?(line)}" 

And the output for the line that shouldn't be cleaned:

called on /Users/JackFranklin/Dropbox/Sites/rubygems/rspectest/spec/test_spec.rb:5:in `block (2 levels) in <top (required)>'
cleaned_from_backtrace? true

[jackfranklin]

Sooooo I figured out what it is.

You know I said it would be something stupid? Yeah...

One of the default backtrace regexes searches for /gems/ in the line, and filters on that. This project lives in a folder called rubygems...so it was matching it, hence it would remove that line, end up filtering out every line and then give me a full backtrace.

I'm such an idiot. Sorry for wasting your time guys.

[myronmarston]

@jackfranklin -- No worries. This was subtle and hard to figure out. I'm actually wondering if the /gems/ entry in the default params should be ./\/gems\// so that it only matches if the file includes a directory of gems and not if gems is anywhere in the full file path.

@dchelimsky - Any idea if making this change would break anyone? Are there any known ruby/rubygems installations that install gems into a directory that has gems in the path but not as a stand-alone segment of the path?

[jackfranklin]

@myronmarston I did wonder if /gems/ is potentially a little too generic - I could imagine a few people have a folder for work they do on Gems - naming it gems or similar isn't entirely unreasonable.

[dchelimsky]

Doubtful that there is any code outside rspec's own specs depending on the format of the output so I don't think it would be a breaking change.

[myronmarston]

Doubtful that there is any code outside rspec's own specs depending on the format of the output so I don't think it would be a breaking change.

I'm not concerned about it breaking anyone's spec suite. I'm more wondering if making this change could cause extra-verbose output for some users when they upgrade to a version that includes this change. If, for example, there's a way of installing ruby/rubygems (e.g. maybe through one of the ruby package managers?) that causes gems to be installed in a path like .../rubygems/... rather than .../gems/... -- then the current pattern would work for them, but changing it as we've proposed would cause verbose output. Ultimately, users can customize the pattern list, of course, so it's probably not too much to worry about...but I'd like the filter list to work well for as many users as possible, and I'd hate to make this change only to discover later that lots of users started to get extra verbose output.

Anyhow, unless I hear evidence suggesting there are common ways to install ruby/rubygems into a path that would be affected by this change, I'll plan to make this change, but to do so in a minor release, not a patch release. Any objections?

[alindeman]

Sounds good to me.

[nacengineer]

FWIW I had this happen to me in RSpec 3 when I was running specs on a gem that was nested in ~/Documents/ruby/gems/... folder. So this still might be an issue for some

[JonRowe]

There's a separate issue surrounding that, see #1604 for discussion