Bisect

Changelog.md

@@ -31,6 +31,9 @@ Enhancements:
   include the example group name (Myron Marson, #1911)
 * Make `let` and `subject` threadsafe. (Josh Cheek, #1858)
 * Add version information into the JSON formatter. (Mark Swinson, #1883)
+* Add `--bisect` CLI option, which will repeatedly run your suite in
+  order to isolate the failures to the smallest reproducible case.
+  (Myron Marston, #1917)
 
 Bug Fixes:
 

features/command_line/bisect.feature

@@ -0,0 +1,161 @@
+Feature: Bisect
+
+  RSpec's `--order random` and `--seed` options help surface flickering examples that only fail when one or more other examples are executed first. It can be very difficult to isolate the exact combination of examples that triggers the failure. The `--bisect` flag helps solve that problem.
+
+  Pass the `--bisect` option (in addition to `--seed` and any other options) and RSpec will repeatedly run subsets of your suite in order to isolate the minimal set of examples that reproduce the same failures.
+
+  At any point during the bisect run, you can hit ctrl-c to abort and it will provide you with the most minimal reproduction command it has discovered so far.
+
+  To get more detailed output (particularly useful if you want to report a bug with bisect), use `--bisect=verbose`.
+
+  Background:
+    Given a file named "lib/calculator.rb" with:
+      """ruby
+      class Calculator
+        def self.add(x, y)
+          x + y
+        end
+      end
+      """
+    And a file named "spec/calculator_1_spec.rb" with:
+      """ruby
+      require 'calculator'
+
+      RSpec.describe "Calculator" do
+        it 'adds numbers' do
+          expect(Calculator.add(1, 2)).to eq(3)
+        end
+      end
+      """
+    And files "spec/calculator_2_spec.rb" through "spec/calculator_9_spec.rb" with an unrelated passing spec in each file
+    And a file named "spec/calculator_10_spec.rb" with:
+      """ruby
+      require 'calculator'
+
+      RSpec.describe "Monkey patched Calculator" do
+        it 'does screwy math' do
+          # monkey patching `Calculator` affects examples that are
+          # executed after this one!
+          def Calculator.add(x, y)
+            x - y
+          end
+
+          expect(Calculator.add(5, 10)).to eq(-5)
+        end
+      end
+      """
+
+  Scenario: Use `--bisect` flag to create a minimal repro case for the ordering dependency
+    When I run `rspec --seed 1234`
+    Then the output should contain "10 examples, 1 failure"
+    When I run `rspec --seed 1234 --bisect`
+    Then bisect should succeed with output like:
+      """
+      Bisect started using options: "--seed 1234"
+      Running suite to find failures... (0.16755 seconds)
+      Starting bisect with 1 failing example and 9 non-failing examples.
+
+      Round 1: searching for 5 non-failing examples (of 9) to ignore: .. (0.30166 seconds)
+      Round 2: searching for 3 non-failing examples (of 5) to ignore: .. (0.30306 seconds)
+      Round 3: searching for 2 non-failing examples (of 3) to ignore: .. (0.33292 seconds)
+      Round 4: searching for 1 non-failing example (of 2) to ignore: . (0.16476 seconds)
+      Round 5: searching for 1 non-failing example (of 1) to ignore: . (0.15329 seconds)
+      Bisect complete! Reduced necessary non-failing examples from 9 to 1 in 1.26 seconds.
+
+      The minimal reproduction command is:
+        rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234
+      """
+    When I run `rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234`
+    Then the output should contain "2 examples, 1 failure"
+
+  Scenario: Ctrl-C can be used to abort the bisect early and get the most minimal command it has discovered so far
+    When I run `rspec --seed 1234 --bisect` and abort in the middle with ctrl-c
+    Then bisect should fail with output like:
+      """
+      Bisect started using options: "--seed 1234"
+      Running suite to find failures... (0.17102 seconds)
+      Starting bisect with 1 failing example and 9 non-failing examples.
+
+      Round 1: searching for 5 non-failing examples (of 9) to ignore: .. (0.32943 seconds)
+      Round 2: searching for 3 non-failing examples (of 5) to ignore: .. (0.3154 seconds)
+      Round 3: searching for 2 non-failing examples (of 3) to ignore: ..
+
+      Bisect aborted!
+
+      The most minimal reproduction command discovered so far is:
+        rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234
+      """
+    When I run `rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234`
+    Then the output should contain "3 examples, 1 failure"
+
+  Scenario: Use `--bisect=verbose` to enable verbose debug mode for more detail
+    When I run `rspec --seed 1234 --bisect=verbose`
+    Then bisect should succeed with output like:
+      """
+      Bisect started using options: "--seed 1234"
+      Running suite to find failures... (0.16528 seconds)
+       - Failing examples (1):
+          - ./spec/calculator_1_spec.rb[1:1]
+       - Non-failing examples (9):
+          - ./spec/calculator_10_spec.rb[1:1]
+          - ./spec/calculator_2_spec.rb[1:1]
+          - ./spec/calculator_3_spec.rb[1:1]
+          - ./spec/calculator_4_spec.rb[1:1]
+          - ./spec/calculator_5_spec.rb[1:1]
+          - ./spec/calculator_6_spec.rb[1:1]
+          - ./spec/calculator_7_spec.rb[1:1]
+          - ./spec/calculator_8_spec.rb[1:1]
+          - ./spec/calculator_9_spec.rb[1:1]
+
+      Round 1: searching for 5 non-failing examples (of 9) to ignore:
+       - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_6_spec.rb[1:1] ./spec/calculator_7_spec.rb[1:1] ./spec/calculator_8_spec.rb[1:1] ./spec/calculator_9_spec.rb[1:1] --seed 1234 (0.15302 seconds)
+       - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] ./spec/calculator_4_spec.rb[1:1] ./spec/calculator_5_spec.rb[1:1] --seed 1234 (0.19708 seconds)
+       - Examples we can safely ignore (4):
+          - ./spec/calculator_6_spec.rb[1:1]
+          - ./spec/calculator_7_spec.rb[1:1]
+          - ./spec/calculator_8_spec.rb[1:1]
+          - ./spec/calculator_9_spec.rb[1:1]
+       - Remaining non-failing examples (5):
+          - ./spec/calculator_10_spec.rb[1:1]
+          - ./spec/calculator_2_spec.rb[1:1]
+          - ./spec/calculator_3_spec.rb[1:1]
+          - ./spec/calculator_4_spec.rb[1:1]
+          - ./spec/calculator_5_spec.rb[1:1]
+       - Round finished (0.35172 seconds)
+      Round 2: searching for 3 non-failing examples (of 5) to ignore:
+       - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_4_spec.rb[1:1] ./spec/calculator_5_spec.rb[1:1] --seed 1234 (0.15836 seconds)
+       - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234 (0.19065 seconds)
+       - Examples we can safely ignore (2):
+          - ./spec/calculator_4_spec.rb[1:1]
+          - ./spec/calculator_5_spec.rb[1:1]
+       - Remaining non-failing examples (3):
+          - ./spec/calculator_10_spec.rb[1:1]
+          - ./spec/calculator_2_spec.rb[1:1]
+          - ./spec/calculator_3_spec.rb[1:1]
+       - Round finished (0.35022 seconds)
+      Round 3: searching for 2 non-failing examples (of 3) to ignore:
+       - Running: rspec ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_2_spec.rb[1:1] --seed 1234 (0.21028 seconds)
+       - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] ./spec/calculator_3_spec.rb[1:1] --seed 1234 (0.1975 seconds)
+       - Examples we can safely ignore (1):
+          - ./spec/calculator_2_spec.rb[1:1]
+       - Remaining non-failing examples (2):
+          - ./spec/calculator_10_spec.rb[1:1]
+          - ./spec/calculator_3_spec.rb[1:1]
+       - Round finished (0.40882 seconds)
+      Round 4: searching for 1 non-failing example (of 2) to ignore:
+       - Running: rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234 (0.17173 seconds)
+       - Examples we can safely ignore (1):
+          - ./spec/calculator_3_spec.rb[1:1]
+       - Remaining non-failing examples (1):
+          - ./spec/calculator_10_spec.rb[1:1]
+       - Round finished (0.17234 seconds)
+      Round 5: searching for 1 non-failing example (of 1) to ignore:
+       - Running: rspec ./spec/calculator_1_spec.rb[1:1] --seed 1234 (0.18279 seconds)
+       - Round finished (0.18312 seconds)
+      Bisect complete! Reduced necessary non-failing examples from 9 to 1 in 1.47 seconds.
+
+      The minimal reproduction command is:
+        rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234
+      """
+    When I run `rspec ./spec/calculator_10_spec.rb[1:1] ./spec/calculator_1_spec.rb[1:1] --seed 1234`
+    Then the output should contain "2 examples, 1 failure"

features/step_definitions/additional_cli_steps.rb

@@ -1,5 +1,7 @@
 require 'rspec/core'  # to fix annoying "undefined method `configuration' for RSpec:Module (NoMethodError)"
 
+require './spec/support/formatter_support'
+
 Then /^the output should contain all of these:$/ do |table|
   table.raw.flatten.each do |string|
     assert_partial_output(string, all_output)
@@ -150,3 +152,34 @@
     File.open("spec/spec_helper.rb", "w") { |f| f.write("") }
   end
 end
+
+Given(/^files "(.*?)" through "(.*?)" with an unrelated passing spec in each file$/) do |file1, file2|
+  index_1 = Integer(file1[/\d+/])
+  index_2 = Integer(file2[/\d+/])
+  pattern = file1.sub(/\d+/, '%s')
+
+  index_1.upto(index_2) do |index|
+    write_file(pattern % index, <<-EOS)
+      RSpec.describe "Spec file #{index}" do
+        example { }
+      end
+    EOS
+  end
+end
+
+Then(/^bisect should (succeed|fail) with output like:$/) do |succeed, expected_output|
+  last_process = only_processes.last
+  expect(last_exit_status).to eq(succeed == "succeed" ? 0 : 1)
+
+  expected = normalize_durations(expected_output)
+  actual   = normalize_durations(last_process.stdout)
+
+  expect(actual.sub(/\n+\Z/, '')).to eq(expected)
+end
+
+When(/^I run `([^`]+)` and abort in the middle with ctrl\-c$/) do |cmd|
+  set_env('RUBYOPT', ENV['RUBYOPT'] + " -r#{File.expand_path("../../support/send_sigint_during_bisect.rb", __FILE__)}")
+  step "I run `#{cmd}`"
+end
+
+World(FormatterSupport)

features/support/env.rb

@@ -1,6 +1,9 @@
 require 'aruba/cucumber'
 
 Before do
+  # Force ids to be printed unquoted for consistency
+  set_env('SHELL', '/usr/bin/bash')
+
   if RUBY_PLATFORM =~ /java/ || defined?(Rubinius)
     @aruba_timeout_seconds = 60
   else

features/support/send_sigint_during_bisect.rb

@@ -0,0 +1,21 @@
+require 'rspec/core'
+RSpec::Support.require_rspec_core "formatters/bisect_progress_formatter"
+
+module RSpec::Core::Formatters
+  BisectProgressFormatter = Class.new(remove_const :BisectProgressFormatter) do
+    RSpec::Core::Formatters.register self
+
+    def bisect_round_finished(notification)
+      return super unless notification.round == 3
+
+      Process.kill("INT", Process.pid)
+      # Process.kill is not a synchronous call, so to ensure the output
+      # below aborts at a deterministic place, we need to block here.
+      # The sleep will be interrupted by the signal once the OS sends it.
+      # For the most part, this is only needed on JRuby, but we saw
+      # the asynchronous behavior on an MRI 2.0 travis build as well.
+      sleep 5
+    end
+  end
+end
+

lib/rspec/core/bisect/coordinator.rb

@@ -0,0 +1,66 @@
+RSpec::Support.require_rspec_core "bisect/server"
+RSpec::Support.require_rspec_core "bisect/runner"
+RSpec::Support.require_rspec_core "bisect/example_minimizer"
+RSpec::Support.require_rspec_core "formatters/bisect_progress_formatter"
+
+module RSpec
+  module Core
+    module Bisect
+      # @private
+      # The main entry point into the bisect logic. Coordinates among:
+      #   - Bisect::Server: Receives suite results.
+      #   - Bisect::Runner: Runs a set of examples and directs the results
+      #     to the server.
+      #   - Bisect::ExampleMinimizer: Contains the core bisect logic.
+      #   - Formatters::BisectProgressFormatter: provides progress updates
+      #     to the user.
+      class Coordinator
+        def self.bisect_with(original_cli_args, configuration, formatter)
+          new(original_cli_args, configuration, formatter).bisect
+        end
+
+        def initialize(original_cli_args, configuration, formatter)
+          @original_cli_args = original_cli_args
+          @configuration     = configuration
+          @formatter         = formatter
+        end
+
+        def bisect
+          @configuration.add_formatter @formatter
+
+          reporter.close_after do
+            repro = Server.run do |server|
+              runner    = Runner.new(server, @original_cli_args)
+              minimizer = ExampleMinimizer.new(runner, reporter)
+
+              gracefully_abort_on_sigint(minimizer)
+              minimizer.find_minimal_repro
+              minimizer.repro_command_for_currently_needed_ids
+            end
+
+            reporter.publish(:bisect_repro_command, :repro => repro)
+          end
+
+          true
+        rescue BisectFailedError => e
+          reporter.publish(:bisect_failed, :failure_explanation => e.message)
+          false
+        end
+
+      private
+
+        def reporter
+          @configuration.reporter
+        end
+
+        def gracefully_abort_on_sigint(minimizer)
+          trap('INT') do
+            repro = minimizer.repro_command_for_currently_needed_ids
+            reporter.publish(:bisect_aborted, :repro => repro)
+            exit(1)
+          end
+        end
+      end
+    end
+  end
+end