Improve command failure message

[deivid-rodriguez]

Summary

Show useful debugging information when the :be_successfully_executed matcher fails.

Details

I was debugging a cucumber suite, and getting this error:

Using the default profile...
.F-----------

(::) failed steps (::)

expected "bundle exec rake part1" to be successfully executed (RSpec::Expectations::ExpectationNotMetError)
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-support-3.9.0/lib/rspec/support.rb:97:in `block in <module:Support>'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-support-3.9.0/lib/rspec/support.rb:106:in `notify_failure'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/fail_with.rb:35:in `fail_with'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:40:in `handle_failure'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:27:in `with_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/expectation_target.rb:65:in `to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/aruba-0.14.12/lib/aruba/api/commands.rb:307:in `run_command_and_stop'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/aruba-0.14.12/lib/aruba/cucumber/command.rb:15:in `/^I successfully run `(.*?)`(?: for up to ([\d.]+) seconds)?$/'
features/test_unit_collate.feature:13:in `When I successfully run `bundle exec rake part1`'

Failing Scenarios:
cucumber features/test_unit_collate.feature:6 # Scenario: 

1 scenario (1 failed)
13 steps (1 failed, 11 skipped, 1 passed)
0m0.534s

Unfortunately the aruba matcher is not giving me a lot of information for figuring it out.

After my changes, I would get the following output, more helpful I think:

Using the default profile...
.F-----------

(::) failed steps (::)

Expected `bundle exec rake part1` to succeed but got non zero exit status and the following output:

/home/deivid/.rbenv/versions/2.6.5/bin/ruby -w -I"lib:lib" -I"/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rake-12.3.3/lib" "/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rake-12.3.3/lib/rake/rake_test_loader.rb" "test/faked_test.rb" "test/meta_magic_test.rb" "test/some_class_test.rb" 

File does not exist: test_helper

rake aborted!
Command failed with status (1): [ruby -w -I"lib:lib" -I"/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rake-12.3.3/lib" "/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rake-12.3.3/lib/rake/rake_test_loader.rb" "test/faked_test.rb" "test/meta_magic_test.rb" "test/some_class_test.rb" ]
/home/deivid/.rbenv/versions/2.6.5/bin/bundle:23:in `load'
/home/deivid/.rbenv/versions/2.6.5/bin/bundle:23:in `<main>'
Tasks: TOP => part1
(See full trace by running task with --trace)

 (RSpec::Expectations::ExpectationNotMetError)
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-support-3.9.0/lib/rspec/support.rb:97:in `block in <module:Support>'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-support-3.9.0/lib/rspec/support.rb:106:in `notify_failure'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/fail_with.rb:35:in `fail_with'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:40:in `handle_failure'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:27:in `with_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.9.0/lib/rspec/expectations/expectation_target.rb:65:in `to'
/home/deivid/Code/aruba/lib/aruba/api/commands.rb:198:in `run_command_and_stop'
/home/deivid/Code/aruba/lib/aruba/cucumber/command.rb:12:in `/^I successfully run `(.*?)`(?: for up to ([\d.]+) seconds)?$/'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/invoke_in_world.rb:27:in `cucumber_instance_exec_in'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/step_definition.rb:110:in `invoke'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/step_match.rb:31:in `invoke'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/step_match.rb:24:in `block in activate'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/action.rb:24:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/step.rb:32:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:104:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:51:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:27:in `test_step'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/step.rb:17:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:28:in `block (3 levels) in describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:27:in `each'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:27:in `block (2 levels) in describe_to'
/home/deivid/Code/aruba/lib/aruba/platforms/local_environment.rb:22:in `call'
/home/deivid/Code/aruba/lib/aruba/platforms/unix_platform.rb:78:in `with_environment'
/home/deivid/Code/aruba/lib/aruba/api/core.rb:201:in `with_environment'
/home/deivid/Code/aruba/lib/aruba/cucumber/hooks.rb:7:in `block in <top (required)>'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/invoke_in_world.rb:39:in `instance_exec'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/invoke_in_world.rb:39:in `block in cucumber_instance_exec_in'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/invoke_in_world.rb:54:in `cucumber_run_with_backtrace_filtering'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/invoke_in_world.rb:27:in `cucumber_instance_exec_in'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/glue/hook.rb:21:in `invoke'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/runtime/support_code.rb:131:in `block (2 levels) in find_around_hooks'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/around_hook.rb:17:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:104:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:51:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:34:in `around_hook'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/around_hook.rb:12:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:120:in `block (2 levels) in compose_around_hooks'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/prepare_world.rb:22:in `block in test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/around_hook.rb:17:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:104:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:51:in `execute'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:34:in `around_hook'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/around_hook.rb:12:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:120:in `block (2 levels) in compose_around_hooks'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:121:in `compose_around_hooks'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:26:in `block in describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/runner.rb:19:in `test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:25:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/prepare_world.rb:11:in `test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:25:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:57:in `test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/retry.rb:18:in `test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:25:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/quit.rb:12:in `test_case'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/case.rb:25:in `describe_to'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/broadcast_test_run_started_event.rb:21:in `block in done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/broadcast_test_run_started_event.rb:20:in `map'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/filters/broadcast_test_run_started_event.rb:20:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/filters/locations_filter.rb:20:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/filter.rb:62:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/test/filters/tag_filter.rb:18:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/compiler.rb:24:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core/gherkin/parser.rb:39:in `done'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core.rb:32:in `parse'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-core-3.2.1/lib/cucumber/core.rb:21:in `compile'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/runtime.rb:75:in `run!'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/lib/cucumber/cli/main.rb:34:in `execute!'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/cucumber-3.1.2/bin/cucumber:9:in `<top (required)>'
/home/deivid/.rbenv/versions/2.6.5/bin/cucumber:23:in `load'
/home/deivid/.rbenv/versions/2.6.5/bin/cucumber:23:in `<top (required)>'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:74:in `load'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:74:in `kernel_load'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli/exec.rb:28:in `run'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:465:in `exec'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:27:in `dispatch'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/cli.rb:18:in `start'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/exe/bundle:30:in `block in <top (required)>'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
/home/deivid/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.0.2/exe/bundle:22:in `<top (required)>'
/home/deivid/.rbenv/versions/2.6.5/bin/bundle:23:in `load'
/home/deivid/.rbenv/versions/2.6.5/bin/bundle:23:in `<main>'
features/test_unit_collate.feature:13:in `When I successfully run `bundle exec rake part1`'

Failing Scenarios:
cucumber features/test_unit_collate.feature:6 # Scenario: 

1 scenario (1 failed)
13 steps (1 failed, 11 skipped, 1 passed)
0m0.525s

Motivation and Context

I'd like aruba to give me the output of the failed command, in case it failed, so I can debug what happened.

How Has This Been Tested?

I tested this manually against my project. I had a quick look into adding a test but I didn't see any existing tests for failure messages.

Screenshots (if appropriate):

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to not work as expected)
• Refactoring (cleanup of codebase without changing any existing functionality)
• Update documentation

Checklist:

• I've added tests for my code
• My change requires a change to the documentation.
• I have updated the documentation accordingly.