Add new ParallelTests::RSpec::VerboseFormatter for enhanced debugging (…

…#926)

The new formatter allows users of parallel_rspec to more easily obtain
detailed information about the examples running as they occur in real
time.

Background:

In my project, it was observed that an RSpec example would hang
intermittently on CI. At first, no team member was able to make this
reliably fail enough on CI to facilitate debugging and no one was able
to reproduce locally at all. The hang only occurred with parallel tests
running and never with just the "rspec" command.

In an attempt to gather more information, we began using the RSpec
"documentation" formatter which outputs the "description", "context",
and "it" strings. Unfortunately, when running in parallel, the output
from different processes will interleave with one another making it
extremely difficult to understand which example is responsible for the
observed hang.

Solution:

Build a "documentation-like" formatter that plays nicely with the
parallel_tests framework. The new formatter always ouputs all
information on a single line to avoid important details from different
processes interleaving with one another. This means the "describe" and
"context" strings will be repeated across multiple "it" blocks.

To further assist, the formatter include the PID and parallel process
number to help identify which subprocess hangs and which one continues.
The output will look something like:

```
[14403] [2] [STARTED] Foo foo
[14402] [1] [STARTED] Bar bar
[14402] [1] [PASSED] Bar bar
```

In the output above, it is clear the "Foo foo" example is still running.

Using this formatter, our project's team was able to successfully
identify the example causing the intermittent hang and then address it.
As such, I'm hoping that this may be useful for a larger audience.

CHANGELOG.md

@@ -3,6 +3,8 @@
 ## Unreleased
 
 - Sort the output of `runtime_logger` for RSpec to show slowest tests first
+- Add new `ParallelTests::RSpec::VerboseFormatter` to output detailed
+  information about each example as it starts and finishes.
 
 ### Breaking Changes
 

Readme.md

@@ -183,6 +183,22 @@ To rerun failures:
 
     cucumber @tmp/cucumber_failures.log
 
+Formatters
+==========
+
+RSpec: VerboseFormatter
+
+Output the RSpec PID, parallel process number, spec status, and the full
+example description. The formatter outputs one line when starting an example
+and then again when finishing. Use like the RSpec documentation but plays
+nicely with parallel processes.
+
+Usage:
+
+```console
+$ parallel_rspec -- --format ParallelTests::RSpec::VerboseFormatter --
+```
+
 Setup for non-rails
 ===================
 

lib/parallel_tests/rspec/verbose_formatter.rb

@@ -0,0 +1,62 @@
+# frozen_string_literal: true
+
+require 'rspec/core/formatters/base_text_formatter'
+require 'parallel_tests/rspec/runner'
+
+class ParallelTests::RSpec::VerboseFormatter < RSpec::Core::Formatters::BaseTextFormatter
+  RSpec::Core::Formatters.register(
+    self,
+    :example_group_started,
+    :example_group_finished,
+    :example_started,
+    :example_passed,
+    :example_pending,
+    :example_failed
+  )
+
+  def initialize(output)
+    super
+    @line = []
+  end
+
+  def example_group_started(notification)
+    @line.push(notification.group.description)
+  end
+
+  def example_group_finished(_notification)
+    @line.pop
+  end
+
+  def example_started(notification)
+    @line.push(notification.example.description)
+    output_formatted_line('STARTED', :yellow)
+  end
+
+  def example_passed(_passed)
+    output_formatted_line('PASSED', :success)
+    @line.pop
+  end
+
+  def example_pending(_pending)
+    output_formatted_line('PENDING', :pending)
+    @line.pop
+  end
+
+  def example_failed(_failure)
+    output_formatted_line('FAILED', :failure)
+    @line.pop
+  end
+
+  private
+
+  def output_formatted_line(status, console_code)
+    prefix = ["[#{Process.pid}]"]
+    if ENV.include?('TEST_ENV_NUMBER')
+      test_env_number = ENV['TEST_ENV_NUMBER'] == '' ? 1 : Integer(ENV['TEST_ENV_NUMBER'])
+      prefix << "[#{test_env_number}]"
+    end
+    prefix << RSpec::Core::Formatters::ConsoleCodes.wrap("[#{status}]", console_code)
+
+    output.puts [*prefix, *@line].join(' ')
+  end
+end

spec/parallel_tests/rspec/verbose_formatter_spec.rb

@@ -0,0 +1,52 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe ParallelTests::RSpec::VerboseFormatter do
+  def run(command)
+    result = IO.popen(command, err: [:child, :out], &:read)
+    raise "FAILED: #{result}" unless $?.success?
+    result
+  end
+
+  it 'outputs verbose information' do
+    repo_root = Dir.pwd
+
+    use_temporary_directory do
+      # setup simple structure
+      FileUtils.mkdir "spec"
+
+      File.write "spec/foo_spec.rb", <<-RUBY
+        describe "Foo" do
+          it "foo" do
+            sleep 0.5
+            expect(true).to be(true)
+          end
+        end
+      RUBY
+
+      File.write "spec/bar_spec.rb", <<-RUBY
+        describe "Bar" do
+          it "bar" do
+            sleep 0.25111
+            expect(true).to be(true)
+          end
+        end
+      RUBY
+
+      result = run [
+        "ruby",
+        "#{repo_root}/bin/parallel_rspec",
+        "-n", "2",
+        "--",
+        "--format", "ParallelTests::RSpec::VerboseFormatter",
+        "--"
+      ]
+
+      expect(result).to match(/^\[\d+\] \[(1|2)\] \[STARTED\] Foo foo$/)
+      expect(result).to match(/^\[\d+\] \[(1|2)\] \[PASSED\] Foo foo$/)
+      expect(result).to match(/^\[\d+\] \[(1|2)\] \[STARTED\] Bar bar$/)
+      expect(result).to match(/^\[\d+\] \[(1|2)\] \[PASSED\] Bar bar$/)
+    end
+  end
+end

spec/spec_helper.rb

@@ -8,6 +8,7 @@
 require 'parallel_tests/test/runtime_logger'
 require 'parallel_tests/rspec/runtime_logger'
 require 'parallel_tests/rspec/summary_logger'
+require 'parallel_tests/rspec/verbose_formatter'
 
 String.class_eval do
   def strip_heredoc