rspec Bisect Runs Indefinitely

Question

I'm seeing some unexpected behavior regarding rspec --bisect when running on circleci. Often times the bisect runs indefinitely until it times out after 5 hours. Bisecting appears to be working initially, but once it reaches the expected end, it begins to slowly examine subsets in the opposite direction until it times out.

My Env:
Ruby 2.4.2p198 (2017-09-14 revision 59899) [x86_64-darwin16]
RSpec 3.7
- rspec-core 3.7.1
- rspec-expectations 3.7.0
- rspec-mocks 3.7.0
- rspec-rails 3.7.2
- rspec-support 3.7.1

The command:
DISABLE_SPRING=true RAILS_ENV=test bundle exec rspec #{all_specs} --order rand:21237 --bisect

Running suite to find failures... (1 minute 5.94 seconds)
Starting bisect with 1 failing example and 424 non-failing examples.
Checking that failure(s) are order-dependent... failure appears to be order-dependent

Round 1: bisecting over non-failing examples 1-424 .. multiple culprits detected - splitting candidates (1 minute 26.35 seconds)
Round 2: bisecting over non-failing examples 1-212 .. multiple culprits detected - splitting candidates (1 minute 29.08 seconds)
Round 3: bisecting over non-failing examples 1-106 .. multiple culprits detected - splitting candidates (1 minute 26.57 seconds)
Round 4: bisecting over non-failing examples 1-53 .. multiple culprits detected - splitting candidates (1 minute 23.85 seconds)
Round 5: bisecting over non-failing examples 1-27 .. multiple culprits detected - splitting candidates (1 minute 29.03 seconds)
Round 6: bisecting over non-failing examples 1-14 .. multiple culprits detected - splitting candidates (1 minute 21.54 seconds)
Round 7: bisecting over non-failing examples 1-7 .. multiple culprits detected - splitting candidates (1 minute 28 seconds)
Round 8: bisecting over non-failing examples 1-4 .. multiple culprits detected - splitting candidates (1 minute 30.43 seconds)
Round 9: bisecting over non-failing examples 1-2 .. multiple culprits detected - splitting candidates (1 minute 28.99 seconds)
Round 10: bisecting over non-failing examples 3-4 .. multiple culprits detected - splitting candidates (1 minute 26.5 seconds)
Round 11: bisecting over non-failing examples 5-7 .. multiple culprits detected - splitting candidates (1 minute 54.99 seconds)
Round 12: bisecting over non-failing examples 5-6 .. multiple culprits detected - splitting candidates (1 minute 42.05 seconds)
Round 13: bisecting over non-failing examples 8-14 .. multiple culprits detected - splitting candidates (1 minute 46.97 seconds)
Round 14: bisecting over non-failing examples 8-11 .. multiple culprits detected - splitting candidates (1 minute 38.02 seconds)
Round 15: bisecting over non-failing examples 8-9 .. multiple culprits detected - splitting candidates (1 minute 35.84 seconds)
Round 16: bisecting over non-failing examples 10-11 .. multiple culprits detected - splitting candidates (1 minute 23.13 seconds)
Round 17: bisecting over non-failing examples 12-14 .. multiple culprits detected - splitting candidates (1 minute 23.11 seconds)
Round 18: bisecting over non-failing examples 12-13 .. multiple culprits detected - splitting candidates (1 minute 36.75 seconds)
Round 19: bisecting over non-failing examples 15-27 .. multiple culprits detected - splitting candidates (1 minute 29.76 seconds)
Round 20: bisecting over non-failing examples 15-21 .. multiple culprits detected - splitting candidates (1 minute 39.97 seconds)
Round 21: bisecting over non-failing examples 15-18 .. multiple culprits detected - splitting candidates (1 minute 35.21 seconds)
Round 23: bisecting over non-failing examples 17-18 .. multiple culprits detected - splitting candidates (1 minute 29.7 seconds)
Round 24: bisecting over non-failing examples 19-21 .. multiple culprits detected - splitting candidates (1 minute 29.41 seconds)
Round 25: bisecting over non-failing examples 19-20 .. multiple culprits detected - splitting candidates (1 minute 31.41 seconds)
Round 26: bisecting over non-failing examples 22-27 .. multiple culprits detected - splitting candidates (1 minute 25.67 seconds)
...
Round 183: bisecting over non-failing examples 181-186 .. multiple culprits detected - splitting candidates (1 minute 58.92 seconds)
Round 184: bisecting over non-failing examples 181-183 .. multiple culprits detected - splitting candidates (1 minute 44.64 seconds)
Build timed out after 5h0m0s

Any idea what causes bisect to behave this way? Thanks!

Charterhouse

Answer 1

I can have some pointers for you on how to continue:

First of all - at any point you can Ctr-C the process and rspec will output the so-far-minimal command to reproduce (hopefully it'll be smaller set that the {all_specs}.

You should try this before it times out. There's a chance that the number of possible combinations to check is so big it just times out (e.g. it would succeed if it had more time). Then use this minimal command to run --bisect again.

You can also try --bisect=verbose to get a better understanding of what is going on behind the scenes.

Your whole suite seems to be pretty fast (~2 minutes) so it's weird it times out. There's (infinitely small) chance that the failure is only when running the whole suite in that particular order. If that's the case - you're basically doomed.

Quintillion

hahaha, there is a small chance of doom, yes - thanks for the sanity check – Charterhouse

By doomed I meant you'll not find "general" answer on the internet. It's probably still fixable, but working with this particular codebase. – Quintillion

Answer 2

It was a bug, and it has been recently fixed and released with rspec-core 3.9.1.

Openwork

Check out version 3.9.3 as well github.com/rspec/rspec-core/blob/v3.9.3/Changelog.md which had a related bug fixed. – Footwork

Answer 3

For me, the issue was that --bisect seems to do nothing if you're using spring. Even with verbose, it gives no useful output. My test suite should have ran in 10 seconds.

Recuperative