rspec command exits with non zero status, 0 failures

[JonRowe]

When running our work projects test suite using rspec, the process sometimes (not always) will return an exit status of 1, even though there was no failures, the output on CI looks like:

Finished in 1 minute 44.48 seconds
2237 examples, 0 failures, 2 pending

Randomized with seed 63250

RSpec Finished with status: 1 # this is printing $?

The command being run is: ruby -S rspec spec/ --failure-exit-code 2

Rspec is version: 2.14.7, ruby 2.0.0p353

I've put some logging around the at_exit method to see if any processes were fiddling with the status, I'm printing the status before and after the at_exit is run, the only registered hook is sinatra, this one here: https://github.com/sinatra/sinatra/blob/master/lib/sinatra/main.rb#L25 but i'm logging the exit status before and after the block is executing and it's a 0 both before and after.

I'm also logging all calls to abort exit and exit! and none of them seem to be getting called causing the exit.

I'm not sure where else to look to hunt down the issue? It's hard to reproduce as running a subset of the tests is always fine and it happens on some machines more often than others.

The only other way I can think that the script would return a status of 1 is if there were an exception thrown, but there's no output to indicate that's happening (although it could be). Maybe there's a way I could log if there's an uncaught exception to check?

[myronmarston]

It's hard to guess what the problem is without having a reproducible example. You might try upgrading to RSpec 3.0.0.beta1, though: it no longer uses at_exit to run the specs, so it should make it easier to track down the source of the problem if the problem remains.

[mariovisic]

@myronmarston I had a go at bumping to 3.x last week, there's some changes that are causing a lot of tests to pass though (600 or so I think) so it'll take some time.

[mariovisic]

Anything else you can think of that might help?

[myronmarston]

@myronmarston I had a go at bumping to 3.x last week, there's some changes that are causing a lot of tests to pass though (600 or so I think) so it'll take some time.

I put together step-by-step instructions to upgrade to RSpec 3:

http://myronmars.to/n/dev-blog/2013/11/rspec-2-99-and-3-0-betas-have-been-released#the_upgrade_process

Did you try them? If you're running into difficulties while following those steps, please let us know!

[mariovisic]

Ooooh, didn't see those instructions, just bumped the gem version, i'll go through it a bit later and let you know how I go, thanks :)

[sevenseacat]

as far as I knew, pending tests also made it return 1.

[myronmarston]

as far as I knew, pending tests also made it return 1.

Pending tests should not make it return non-zero: if it did, I'd consider that a bug, but I've never seen it do that.

[sevenseacat]

I have on our CI box, I'll try and dig up some details.

[myronmarston]

@Karpah -- are you talking about the pending block form?

it "does something" do
  pending "waiting on an upstream fix" do
    # the test code
  end
end

If so, that makes sense, and is a case I wasn't thinking about when I wrote the comment above. The pending block form runs the block, and, as long as the block fails, makes the test pending (and would not cause a non-zero exit status). If the block passes, then it marks the test as failed with a message like "expected example to be fail but passed", and it'll yield a non-zero exit status.

[sevenseacat]

Please ignore me, I can't remember where I did this at all and may have just been mistaken :/

[mariovisic]

@myronmarston Upgraded, went very smoothly, your deprication approach was excellent by the way so well done. I do have 1 error after going from 2.99 to 3.0:

     Failure/Error: Unable to find matching line from backtrace
     NoMethodError:
       undefined method `matches_name_but_not_args' for #<RSpec::Mocks::SimpleMessageExpectation:0x007ff659d9a420>

[mariovisic]

I've opened an issue for the failing test over here: rspec/rspec-mocks#480

I'll let you know how I go with the failing 1 status on 3.0 once I can get it to run a few times over CI

[mariovisic]

The issue still occurs on 3.0, the upgrade hasn't helped at all unfortunately.

[myronmarston]

The issue still occurs on 3.0, the upgrade hasn't helped at all unfortunately.

That tells us that it was definitely not the at_exit hook in RSpec 2.x, though. That's useful information.

RSpec only has two places that call exit:

• rspec-core/lib/rspec/core/runner.rb

  Line 32 in 6950746

  exit(status) if status != 0

• rspec-core/lib/rspec/core/runner.rb

  Line 65 in 6950746

  exit!(1) if RSpec.wants_to_quit

The first is the normal place that exits with 0/non-zero (usually 1, unless you have set the failure exit code option) after running the specs. The second is in the handler where rspec handles ctrl-c: it sets a flag, tries to do the necessary cleanup and exit, and if ctrl-c is received again before the cleanup completes, it immediately exits with a status of 1.

I had forgotten this until now, but Kernel#abort can also cause the process to exit. RSpec has two places that call that:

• rspec-core/lib/rspec/core/option_parser.rb

  Line 20 in 6950746

  abort "#{e.message}\n\nPlease use --help for a listing of valid options"

• rspec-core/lib/rspec/core/rake_task.rb

  Line 100 in 6950746

  abort("#{command} failed") if fail_on_error unless success

The first is used when you run rspec with invalid options. The second is used when you use the rake task to run the specs.

It seems unlikely that any of these 4 places are at fault, but you can always put some logging in place to confirm. It seems far more likely that it's something else in either your code or in a gem you are loading that is causing this. RSpec can't prevent that.

You might try monkey patching exit like so:

::Kernel.class_eval do
  alias old_exit exit
  def exit(*args)
    puts "Exiting with #{args.inspect}"
    puts caller.join("\n")
    puts
    old_exit(*args)
  end
end

You could patch exit! and abort similarly.

Good luck!

[mariovisic]

Thanks

That give me a bit to go on with. When I supply a failure exit code of 2 on the command line, when rspec exits (with 0 failures) it will return 1 as the status, not 2.

BTW: There's actually a small bug in the rake runner, because it's just calling abort on error, it will return a 1 status, not whatever status is set, you can see that here:

rspec-core/lib/rspec/core/rake_task.rb

Line 100 in 6950746

abort("#{command} failed") if fail_on_error unless success

I was actually already monkey patching a bunch of methods on Kernel to see if they were called but nothing would come up, I've got the logging around exit, exit! abort and fail

I can't see any other methods that would cause the program to exit, the only other thing I can think of is an uncaught exception, but this should print something to the screen, which it's not doing.

Anyways, i'll dig a bit further and keep you posted on what I find.

[JonRowe]

The call to abort prevents stack traces being dumped, it's a work around for rake's behaviour see 194a525

[mariovisic]

Oh I see, abort seems to just print to STDERR and then exit with a 1 status, could just do the same in 2 steps:

if fail_on_error && !success
  $stderr.puts("#{command} failed")
  exit($?)
end

I'm not sure about the rake bug though, would it play nicely with exit over abort ?

[JonRowe]

exit doesn't take a message

[myronmarston]

There may be an improvement we can make to the rake task but for now I'd recommend you try running your specs with the rspec command instead of rake. That will eliminate rake from the equation and may give us clues. I personally never use the rake task anyway: it's less flexible and adds overhead.

[mariovisic]

It takes an exit status, $? is just the exit status of the system() command if it has failed, it should be a number

[JonRowe]

I meant exit isn't a direct replacement for abort but I see I just misread the comment out of context.

[JonRowe]

This branch should exit correctly. /cc @myronmarston @mariovisic

[myronmarston]

Looks fine, but I think it could use a spec.

[JonRowe]

Spec added ;)

[JonRowe]

Ok so this is specced and working now, so merging since there were no objections. @mariovisic if you use the master branch this should work for you.

[mariovisic]

So after disabling simplecov in the build, the issues seem have gone away; there's been 10 builds in a row that have been green. This is very odd as simplecov isn't set to raise an exceptions if the test coverage drops or is below a certain amount, and as I mentioned before there's no output when the program returns 1.

I've had a quick look through the simplecov code and can't find anything too obvious. I'll open an issue over there if I can identify more specifics about what is causing the error.

Thanks @myronmarston and @JonRowe for your help :)