--bisect failed due to inconsistent ordering after 6 rounds

[shrik450]

Subject of the issue

Hey. I found an ordering based test issue and promptly started a bisect. We don't use random ordering, so I didn't run with --seed.

Your environment

• Ruby version: 2.3.1
• rspec-core version: 3.6.0

Expected behavior

Since the ordering is constant, it shouldn't fail in the first place, but even if it does, it should've failed much earlier.

Actual behavior

Here's the output:

rspec --bisect 
Bisect started using options: ""
Running suite to find failures... (39 minutes 59 seconds)
Starting bisect with 31 failing examples and 1070 non-failing examples.
Checking that failure(s) are order-dependent... failure appears to be order-dependent

Round 1: bisecting over non-failing examples 1-1070 multiple culprits detected - splitting candidates (865 minutes 49 seconds)
Round 3: bisecting over non-failing examples 1-268 multiple culprits detected - splitting candidates (91 minutes 24 seconds)
Round 4: bisecting over non-failing examples 1-134 multiple culprits detected - splitting candidates (78 minutes 9 seconds)
Round 5: bisecting over non-failing examples 1-67 multiple culprits detected - splitting candidates (91 minutes 15 seconds)
Round 6: bisecting over non-failing examples 1-34 multiple culprits detected - splitting candidates (86 minutes 48 seconds)
Round 7: bisecting over non-failing examples 1-17

Bisect failed!

The example ordering is inconsistent. `--bisect` relies upon consistent ordering (e.g. by passing `--seed` if you're using random ordering) to work properly.

[pirj]

Seems similar to #2489, can you please check if it's not a duplicate?

[shrik450]

I don't think it is - OP in that issue did use random ordering, and it failed in round 1. We don't, and it went quite a few rounds before failing.

[JonRowe]

What ordering are you using? The bisect relies on consistent ordering and the check is quite basic, it just checks that the bisects sub ordering is the same as it was when it was first run.

[shrik450]

We didn't configure any ordering, and none of the tests have any ordering specified, so it defaults to defined. The only thing I'm confused by is why it went multiple rounds before it picked up on inconsistent ordering, as if the ordering was unstable it should've been caught in any of the six preceding rounds.

[JonRowe]

What OS / filesystem are you using? What filters if any are you applying? You haven't provided any steps to reproduce this so its a bit hard to determine what is interacting with the ordering here. Check that you don't have a .rspec file defining ordering in your project or your home folder.

The number of steps is irrelevant, the bisector is essentially creating a new spec run each time with a subset of specs, so they are loaded again and rerun, what the bisector does to check the ordering is use the full set of example ids and intersect them with this specific runs ordering, then compares it back to the runs ordering.

E.g. ~[1,2,3,4,5,6,7,8,10] & [4,5,6] will return [4,5,6] which will be == whilst [1,2,3,4,5,6,7,8,10] & [4,6,5] will return [4] and will not be.~

Edit: this is an oversimplified example, and isn't actually executable, but the gist remains the same.

So the ordering is changing, we just need to figure out why.

[shrik450]

I'm on macOS Mojave. I've checked my .rspec and spec_helper files, and there's no ordering defined in the .rspec and the config.order = :random which the spec_helper was generated with was commented out (2 years ago, according to git). I'm not sure how to provide steps to reproduce, given that the test suite is large (>1000 tests, as in the output above), so if I can get any help with what would be useful to detect any issues I'd be happy to provide them.

[JonRowe]

Are you comfortable monkey patching? The easiest way would be to apply this patch to see why the output is changing:

module DebugMonkeyPatch
  def abort_if_ordering_inconsistent(results)
    expected_order = all_example_ids & results.all_example_ids
    puts "expected_order = all_example_ids & results.all_example_ids"
    puts "#{expected_order.inspect} = #{all_example_ids.inspect} & #{results.all_example_ids.inspect}"
    return if expected_order == results.all_example_ids

    raise BisectFailedError, "\n\nThe example ordering is inconsistent. " \
      "`--bisect` relies upon consistent ordering (e.g. by passing " \
      "`--seed` if you're using random ordering) to work properly."
  end
end

module RSpec
  module Core
    module Bisect
      class ExampleMinimizer
        prepend DebugMonkeyPatch
      end
    end
  end
end

[JonRowe]

If you put that in a file in your directory and require it in your spec_helper it should run with the bisector and output the ordering.

[shrik450]

Thanks - I just got off work, so I'll apply it on Monday and get back with the results.

[shrik450]

Due to deadlines I fixed the order-dependent failure manually, but I took a backup copy of the codebase before I fixed it, so I'll run the monkey patched bisect when I have some time and put the results here.

[cmrd-senya]

CC @JonRowe

It seems there is a bug in how bisect groups examples that are spread across different files.

Here is a branch on my fork of rspec-core: https://github.com/cmrd-senya/rspec-core/commit/57ff3125ebe77d69b7a73beb93ef9c4e8ea3ff31

There I added some specs as a showcase for the bug.

When I call bisect with correct specs in front it finishes correctly and finds the reproduction command:

rspec --order defined --bisect spec/rspec/core/resources/order_dependent/correct_specs.rb spec/rspec/core/resources/order_dependent/order_dependent_specs.rb 

But when I call bisect with the order dependent spec in the beginning it fails with the "order inconsistent" erro:

rspec --order defined --bisect spec/rspec/core/resources/order_dependent/order_dependent_specs.rb  spec/rspec/core/resources/order_dependent/correct_specs.rb

[cmrd-senya]

The irony here is that rspec bisect seems to fail because of the order dependency bug

[pirj]

Do those specs fail when you run it without --bisect, @cmrd-senya ?

[cmrd-senya]

This command

rspec spec/rspec/core/resources/order_dependent/order_dependent_specs.rb 

does fail, yes.

Group
  the first example mutates the global state
  the second example does not mutate the global state
  order-dependent failing example (FAILED - 1)

Failures:

  1) Group order-dependent failing example
     Failure/Error: fail if arr.length > 0
     RuntimeError:
     # ./spec/rspec/core/resources/order_dependent/order_dependent_specs.rb:13:in `block (2 levels) in <top (required)>'
     # ./lib/rspec/core/example.rb:262:in `instance_exec'
     # ./lib/rspec/core/example.rb:262:in `block in run'
     # ./lib/rspec/core/example.rb:508:in `block in with_around_and_singleton_context_hooks'
     # ./lib/rspec/core/example.rb:465:in `block in with_around_example_hooks'
     # ./lib/rspec/core/hooks.rb:486:in `block in run'
     # ./lib/rspec/core/hooks.rb:626:in `block in run_around_example_hooks_for'
     # ./lib/rspec/core/example.rb:350:in `call'
     # ./spec/support/sandboxing.rb:16:in `block (3 levels) in <top (required)>'
     # ./lib/rspec/core/sandbox.rb:29:in `sandboxed'
     # ./spec/support/sandboxing.rb:7:in `block (2 levels) in <top (required)>'
     # ./lib/rspec/core/example.rb:455:in `instance_exec'
     # ./lib/rspec/core/example.rb:455:in `instance_exec'
     # ./lib/rspec/core/hooks.rb:390:in `execute_with'
     # ./lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
     # ./lib/rspec/core/example.rb:350:in `call'
     # ./lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'
     # ./lib/rspec/core/hooks.rb:486:in `run'
     # ./lib/rspec/core/example.rb:465:in `with_around_example_hooks'
     # ./lib/rspec/core/example.rb:508:in `with_around_and_singleton_context_hooks'
     # ./lib/rspec/core/example.rb:259:in `run'
     # ./lib/rspec/core/example_group.rb:644:in `block in run_examples'
     # ./lib/rspec/core/example_group.rb:640:in `map'
     # ./lib/rspec/core/example_group.rb:640:in `run_examples'
     # ./lib/rspec/core/example_group.rb:606:in `run'
     # ./lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'
     # ./lib/rspec/core/runner.rb:121:in `map'
     # ./lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'
     # ./lib/rspec/core/configuration.rb:2067:in `with_suite_hooks'
     # ./lib/rspec/core/runner.rb:116:in `block in run_specs'
     # ./lib/rspec/core/reporter.rb:74:in `report'
     # ./lib/rspec/core/runner.rb:115:in `run_specs'
     # ./lib/rspec/core/runner.rb:89:in `run'
     # ./lib/rspec/core/runner.rb:71:in `run'
     # ./lib/rspec/core/runner.rb:45:in `invoke'
     # ./exe/rspec:4:in `<top (required)>'
     # /home/senya/.rvm/gems/ruby-2.6.2/bin/rspec:23:in `load'
     # /home/senya/.rvm/gems/ruby-2.6.2/bin/rspec:23:in `<main>'
     # /home/senya/.rvm/gems/ruby-2.6.2/bin/ruby_executable_hooks:24:in `eval'
     # /home/senya/.rvm/gems/ruby-2.6.2/bin/ruby_executable_hooks:24:in `<main>'

Finished in 0.00122 seconds (files took 0.20884 seconds to load)
3 examples, 1 failure

Failed examples:

rspec ./spec/rspec/core/resources/order_dependent/order_dependent_specs.rb:12 # Group order-dependent failing example

[cmrd-senya]

It seems that bisect only reliably works when you put the failing spec at the very end of the command line (no matter how many files you add before). But if there are some specs after the failing one - then it's a lottery.