ghostrifle ghostrifle - 4 months ago 12
Ruby Question

RSpec shows backtrace instead of test names

I've upgraded a Rails 4 app to Rails 5. The tests are running fine so far, but the output of the specs is not very tidy. It doesn't show the test names any more but instead shows me some kind of backtrace. So, what am I missing?

Here's the project: https://github.com/polyvision/EasyRaceLapTimer/tree/racemanagement

And here's an example output:

finished race
pilot reached max lap in competition mode
/Users/ghostrifle/development/EasyRaceLapTimer/web/app/adapters/race_session_adapter.rb:248:in `track_lap_time_competition_mode'
/Users/ghostrifle/development/EasyRaceLapTimer/web/app/adapters/race_session_adapter.rb:173:in `track_lap_time'
/Users/ghostrifle/development/EasyRaceLapTimer/web/app/controllers/api/v1/lap_track_controller.rb:39:in `create'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/abstract_controller/base.rb:188:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/rendering.rb:30:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:126:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:126:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:455:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:455:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/abstract_controller/callbacks.rb:19:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/rescue.rb:20:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/notifications.rb:164:in `block in instrument'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/notifications.rb:164:in `instrument'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activerecord-5.0.0/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/abstract_controller/base.rb:126:in `process'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionview-5.0.0/lib/action_view/rendering.rb:30:in `process'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal.rb:190:in `dispatch'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_controller/metal.rb:262:in `dispatch'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/journey/router.rb:39:in `block in serve'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/journey/router.rb:26:in `each'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/journey/router.rb:26:in `serve'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/routing/route_set.rb:725:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/warden-1.2.6/lib/warden/manager.rb:35:in `block in call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/warden-1.2.6/lib/warden/manager.rb:34:in `catch'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/warden-1.2.6/lib/warden/manager.rb:34:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/etag.rb:25:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/conditional_get.rb:38:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/head.rb:12:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:222:in `context'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:216:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/callbacks.rb:36:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/railties-5.0.0/lib/rails/rack/logger.rb:36:in `call_app'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/railties-5.0.0/lib/rails/rack/logger.rb:24:in `block in call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/tagged_logging.rb:70:in `block in tagged'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/tagged_logging.rb:26:in `tagged'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/tagged_logging.rb:70:in `tagged'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/railties-5.0.0/lib/rails/rack/logger.rb:24:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/method_override.rb:22:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/runtime.rb:22:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/activesupport-5.0.0/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/middleware/static.rb:136:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-2.0.1/lib/rack/sendfile.rb:111:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/railties-5.0.0/lib/rails/engine.rb:522:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-test-0.6.3/lib/rack/mock_session.rb:30:in `request'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-test-0.6.3/lib/rack/test.rb:244:in `process_request'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-test-0.6.3/lib/rack/test.rb:124:in `request'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/testing/integration.rb:379:in `process'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/testing/integration.rb:296:in `process_with_kwargs'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/testing/integration.rb:46:in `post'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/actionpack-5.0.0/lib/action_dispatch/testing/integration.rb:497:in `block (2 levels) in <module:Runner>'
/Users/ghostrifle/development/EasyRaceLapTimer/web/spec/controllers/api/v1/lap_track_controller_spec.rb:517:in `block (3 levels) in <top (required)>'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:254:in `instance_exec'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:254:in `block in run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:496:in `block in with_around_and_singleton_context_hooks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:453:in `block in with_around_example_hooks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:471:in `block in run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:611:in `block in run_around_example_hooks_for'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-rails-3.5.1/lib/rspec/rails/example/controller_example_group.rb:191:in `block (2 levels) in <module:ControllerExampleGroup>'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:443:in `instance_exec'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:443:in `instance_exec'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:382:in `execute_with'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:613:in `block (2 levels) in run_around_example_hooks_for'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-rails-3.5.1/lib/rspec/rails/adapters.rb:127:in `block (2 levels) in <module:MinitestLifecycleAdapter>'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:443:in `instance_exec'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:443:in `instance_exec'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:382:in `execute_with'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:613:in `block (2 levels) in run_around_example_hooks_for'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:338:in `call'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:614:in `run_around_example_hooks_for'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/hooks.rb:471:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:453:in `with_around_example_hooks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:496:in `with_around_and_singleton_context_hooks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example.rb:251:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:627:in `block in run_examples'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:623:in `map'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:623:in `run_examples'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:589:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:590:in `block in run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:590:in `map'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/example_group.rb:590:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:113:in `block (3 levels) in run_specs'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:113:in `map'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:113:in `block (2 levels) in run_specs'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/configuration.rb:1836:in `with_suite_hooks'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:112:in `block in run_specs'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/reporter.rb:77:in `report'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:111:in `run_specs'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:87:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:71:in `run'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/lib/rspec/core/runner.rb:45:in `invoke'
/Users/ghostrifle/.rbenv/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rspec-core-3.5.2/exe/rspec:4:in `<top (required)>'
/Users/ghostrifle/.rbenv/versions/2.2.3/bin/rspec:23:in `load'
/Users/ghostrifle/.rbenv/versions/2.2.3/bin/rspec:23:in `<main>'
....pilot: Pilot 1
pilot_num_tracked_laps: 1
max_laps_for_this_race: 5
RaceSessionEventAdapter::perform_for_competition_mode: triggering sound for la

Answer

Your code raises (race_session_adapter.rb:248), rescues (lap_track_controller.rb:40) and prints (lap_track_controller.rb:42-43) that exception. I don't know whether the exception should be raised in your test or not; if not, fix that. In any case, in a Rails app it's usually better to log exceptions to Rails' logger rather than to puts them, since people are more likely to pay attention to the log than to standard output or standard error.

It is interesting that something changed about how Rails 5 or maybe a newer version of RSpec or rspec-rails handles standard output. Maybe someone else knows about that.