Using guard to run integration tests results in undefined method `set_transaction_name' for nil:NilClass

[jhubert]

Issue Description

When I run my rails controller tests using guard I get an error ever since upgrading from 5.3.1 to 5.4.2.

Minitest::UnexpectedError:         NoMethodError: undefined method `set_transaction_name' for nil:NilClass
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/sentry-rails-5.4.2/lib/sentry/rails/controller_transaction.rb:6:in `block in included'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:427:in `instance_exec'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:427:in `block in make_lambda'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:199:in `block in halting'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:512:in `block in invoke_before'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:512:in `each'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:512:in `invoke_before'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:115:in `block in run_callbacks'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/callbacks.rb:137:in `run_callbacks'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/notifications.rb:203:in `block in instrument'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activesupport-6.1.6.1/lib/active_support/notifications.rb:203:in `instrument'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/activerecord-6.1.6.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/abstract_controller/base.rb:165:in `process'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionview-6.1.6.1/lib/action_view/rendering.rb:39:in `process'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/metal.rb:190:in `dispatch'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/test_case.rb:580:in `process_controller_response'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/test_case.rb:499:in `process'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/rails-controller-testing-1.0.5/lib/rails/controller/testing/template_assertions.rb:62:in `process'
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/actionpack-6.1.6.1/lib/action_controller/test_case.rb:398:in `get'
            /Users/jhubert/src/myapp/test/shared/concerns/controller_authentication_test.rb:55:in `block (3 levels) in <module:JSONTest>'
            /Users/jhubert/src/myapp/test/support/helpers/test_routes_helper.rb:96:in `with_test_routing'
            /Users/jhubert/src/myapp/test/shared/concerns/controller_authentication_test.rb:54:in `block (2 levels) in <module:JSONTest>'

The errors seems to be because Sentry.get_current_scope is returning nil and the code expects it to always return a scope.

module Sentry
  module Rails
    module ControllerTransaction
      def self.included(base)
        base.prepend_before_action do |controller|
          Sentry.get_current_scope.set_transaction_name("#{controller.class}##{controller.action_name}"https://github.com/getsentry/sentry-ruby/commit/f94ec04112abfe414324cf064d2d8309122f79e8
        end
      end
    end
  end
end

I'm able to stop the error from happening by handling the nil:

Sentry.get_current_scope&.set_transaction_name("#{controller.class}##{controller.action_name}")

But, this code hasn't changed in 2 years so I'm assuming something else was changed in 5.4.0 that is causing Sentry.get_current_scope to return nil. I've confirmed that Sentry.init is being called before these tests are run so my guess is that something is causing the Thread to disconnect or fail silently between test runs.

Reproduction Steps

Haven't had a chance to test these steps on a plain rails 7 app yet:

1. Write a controller test
2. Run the controller tests with guard (I'm using v 2.18.0 and guard-minitest v 2.4.6)

Expected Behavior

Tests run successfully

Actual Behavior

Tests fail with the following error:

Minitest::UnexpectedError:         NoMethodError: undefined method `set_transaction_name' for nil:NilClass
            /Users/jhubert/.rbenv/versions/3.0.4/lib/ruby/gems/3.0.0/gems/sentry-rails-5.4.2/lib/sentry/rails/controller_transaction.rb:6:in `block in included'

Ruby Version

ruby 3.0.4p208

SDK Version

5.4.2

Integration and Its Version

Rails 7

Sentry Config

No response

[sl0thentr0py]

@jhubert the only thing that changed is we added the Sentry.close API which does do some thread cleanup. Can you check if close is somehow being called in your test by putting a print statement here?

[markedmondson]

@sl0thentr0py I think you're right. I added a *** CLOSING THREAD *** puts:

13:01:35 - INFO - Guard is now watching at '****'
13:02:02 - INFO - Running: test/graphql/resolvers/test.rb
[Zonebie] Setting timezone: ZONEBIE_TZ="Belgrade"
*** CLOSING THREAD ***
Started with run options --guard --seed 9875

ERROR Test#test (1.03s)
Minitest::UnexpectedError:         NoMethodError: undefined method `set_transaction_name' for nil:NilClass

                  Sentry.get_current_scope.set_transaction_name("#{controller.class}##{controller.action_name}")
                                          ^^^^^^^^^^^^^^^^^^^^^
            lib/middleware/validate_request_params.rb:24:in `call'
            lib/ruby_ext/rack_method_override_skipping.rb:9:in `call'

Any idea on what my be causing the premature at_exit?

[sl0thentr0py]

@markedmondson so it's only with guard? I don't know how guard works, I'd need to read their source. Can you maybe give me a minimal repro with rails + guard or a bunch of precise steps to follow?

[markedmondson]

Yeah, with guard. I'll see what I can do. I would imagine Spring may suffer a similar problem and if not, it could provide a solution.

[adamcooper]

Here is a minimal repository with a reproduction of the issue with rails, guard, sentry: https://github.com/adamcooper/sentry_guard_bug

There are steps in the readme on how to reproduce the issue. Let me know if you have questions.

You'll notice that running rails test works perfectly but running bundle exec guard doesn't work. I only added Sentry on the final commit and before adding sentry both ways of running the tests work great (rails test, bundle exec guard).

[st0012]

@adamcooper Thank you very much for the repo.

I think this issue is because guard-minitest loads minitest/autorun upfront, which we can see by running guard with -d option:

14:41:51 - DEBUG - Command execution: bundle exec ruby -I"test" -I"spec" -r bundler/setup -r minitest/autorun -r 
./test/channels/application_cable/connection_test.rb -r ./test/controllers/users_controller_test.rb -r 
./test/models/user_test.rb -r ./test/test_helper.rb -e "" -- --guard

If we remove the unnecessary part, we can get a repro command like:

$ bundle exec ruby -I"test" -I"spec" -r bundler/setup -r minitest/autorun -r ./test/controllers/users_controller_test.rb -e ""
Run options: --seed 61936

# Running:

E

Error:
UsersControllerTest#test_the_truth:
NoMethodError: undefined method `set_transaction_name' for nil:NilClass
    test/controllers/users_controller_test.rb:5:in `block in <class:UsersControllerTest>'


rails test test/controllers/users_controller_test.rb:4



Finished in 0.204985s, 4.8784 runs/s, 0.0000 assertions/s.
1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

But if we exclude the minitest/autorun part, it'll pass

$ bundle exec ruby -I"test" -I"spec" -r bundler/setup -r ./test/controllers/users_controller_test.rb -e ""
Run options: --seed 22687

# Running:

.

Finished in 0.205106s, 4.8755 runs/s, 0.0000 assertions/s.
1 runs, 0 assertions, 0 failures, 0 errors, 0 skips

And I think if you use rails test, the upfront minitest/autorun requirement is not needed as rails/test_help also requires it. It's just guard-minitest couldn't predict that so it loads it anyway.

It's still not clear how -r minitest/autorun would mess with at_exit but requiring it in Ruby files doesn't, but I don't have time to dig into it atm.

Solution

When defining the guard :minitest task, add autorun: false, like guard :minitest, autorun: false.

[sl0thentr0py]

@jhubert the only thing that changed is we added the Sentry.close API which does do some thread cleanup. Can you check if close is somehow being called in your test by putting a print statement here?

[markedmondson]

@sl0thentr0py I think you're right. I added a *** CLOSING THREAD *** puts:

13:01:35 - INFO - Guard is now watching at '****'
13:02:02 - INFO - Running: test/graphql/resolvers/test.rb
[Zonebie] Setting timezone: ZONEBIE_TZ="Belgrade"
*** CLOSING THREAD ***
Started with run options --guard --seed 9875

ERROR Test#test (1.03s)
Minitest::UnexpectedError:         NoMethodError: undefined method `set_transaction_name' for nil:NilClass

                  Sentry.get_current_scope.set_transaction_name("#{controller.class}##{controller.action_name}")
                                          ^^^^^^^^^^^^^^^^^^^^^
            lib/middleware/validate_request_params.rb:24:in `call'
            lib/ruby_ext/rack_method_override_skipping.rb:9:in `call'

Any idea on what my be causing the premature at_exit?

[sl0thentr0py]

@markedmondson so it's only with guard? I don't know how guard works, I'd need to read their source. Can you maybe give me a minimal repro with rails + guard or a bunch of precise steps to follow?

[markedmondson]

Yeah, with guard. I'll see what I can do. I would imagine Spring may suffer a similar problem and if not, it could provide a solution.

[adamcooper]

Here is a minimal repository with a reproduction of the issue with rails, guard, sentry: https://github.com/adamcooper/sentry_guard_bug

There are steps in the readme on how to reproduce the issue. Let me know if you have questions.

You'll notice that running rails test works perfectly but running bundle exec guard doesn't work. I only added Sentry on the final commit and before adding sentry both ways of running the tests work great (rails test, bundle exec guard).

[st0012]

@adamcooper Thank you very much for the repo.

I think this issue is because guard-minitest loads minitest/autorun upfront, which we can see by running guard with -d option:

14:41:51 - DEBUG - Command execution: bundle exec ruby -I"test" -I"spec" -r bundler/setup -r minitest/autorun -r 
./test/channels/application_cable/connection_test.rb -r ./test/controllers/users_controller_test.rb -r 
./test/models/user_test.rb -r ./test/test_helper.rb -e "" -- --guard

If we remove the unnecessary part, we can get a repro command like:

$ bundle exec ruby -I"test" -I"spec" -r bundler/setup -r minitest/autorun -r ./test/controllers/users_controller_test.rb -e ""
Run options: --seed 61936

# Running:

E

Error:
UsersControllerTest#test_the_truth:
NoMethodError: undefined method `set_transaction_name' for nil:NilClass
    test/controllers/users_controller_test.rb:5:in `block in <class:UsersControllerTest>'


rails test test/controllers/users_controller_test.rb:4



Finished in 0.204985s, 4.8784 runs/s, 0.0000 assertions/s.
1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

But if we exclude the minitest/autorun part, it'll pass

$ bundle exec ruby -I"test" -I"spec" -r bundler/setup -r ./test/controllers/users_controller_test.rb -e ""
Run options: --seed 22687

# Running:

.

Finished in 0.205106s, 4.8755 runs/s, 0.0000 assertions/s.
1 runs, 0 assertions, 0 failures, 0 errors, 0 skips

And I think if you use rails test, the upfront minitest/autorun requirement is not needed as rails/test_help also requires it. It's just guard-minitest couldn't predict that so it loads it anyway.

It's still not clear how -r minitest/autorun would mess with at_exit but requiring it in Ruby files doesn't, but I don't have time to dig into it atm.

Solution

When defining the guard :minitest task, add autorun: false, like guard :minitest, autorun: false.

[sl0thentr0py]

@st0012 great investigation!
I believe it's just the order in which the at_exits run then.
This is what Minitest.autorun does, so if the SDK's at_exit/close runs before this at_exit, then the SDK stuff will be nil.

I believe we just need better return unless Sentry.initialized? calls in some other places. I'll try to plug some holes.