fix: Safe-navigate to session flusher #2396

ixti · 2024-09-02T16:05:21Z

Sentry.session_flusher is nil-able. And under some circumstances (which I still can't figure out) in specs it's nil causing our spec suite randomly (but as of recent, pretty all the time) fail.

Example failure

     Failure/Error: post(path, env:, headers:, xhr: true)
     
     NoMethodError:
       undefined method `add_session' for nil
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry/hub.rb:251:in `end_session'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry/hub.rb:260:in `with_session_tracking'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry-ruby.rb:411:in `with_session_tracking'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry/rack/capture_exceptions.rb:21:in `block in call'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry/hub.rb:59:in `with_scope'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry-ruby.rb:391:in `with_scope'
     # /home/ixti/.gem/ruby/3.3.4/gems/sentry-ruby-5.19.0/lib/sentry/rack/capture_exceptions.rb:20:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:45:in `call_app'
     # /home/ixti/.gem/ruby/3.3.4/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:26:in `block in call'
     # /home/ixti/.gem/ruby/3.3.4/bundler/gems/semantic_logger-093c0258b053/lib/semantic_logger/base.rb:190:in `block in tagged'
     # /home/ixti/.gem/ruby/3.3.4/bundler/gems/semantic_logger-093c0258b053/lib/semantic_logger/semantic_logger.rb:395:in `named_tagged'
     # /home/ixti/.gem/ruby/3.3.4/bundler/gems/semantic_logger-093c0258b053/lib/semantic_logger/base.rb:197:in `tagged'
     # /home/ixti/.gem/ruby/3.3.4/gems/rails_semantic_logger-4.17.0/lib/rails_semantic_logger/rack/logger.rb:26:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/rack-3.1.7/lib/rack/runtime.rb:24:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/rack-3.1.7/lib/rack/sendfile.rb:114:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/rack-cors-2.0.2/lib/rack/cors.rb:102:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/railties-7.2.1/lib/rails/engine.rb:535:in `call'
     # /home/ixti/.gem/ruby/3.3.4/gems/rack-test-2.1.0/lib/rack/test.rb:360:in `process_request'
     # /home/ixti/.gem/ruby/3.3.4/gems/rack-test-2.1.0/lib/rack/test.rb:153:in `request'
     # ./spec/support/helpers/protobufable_test_helper.rb:76:in `rpc'
     # ./spec/requests/asgard/auth_controller_spec.rb:220:in `block (4 levels) in <top (required)>'
     # /home/ixti/.gem/ruby/3.3.4/gems/webmock-3.23.1/lib/webmock/rspec.rb:39:in `block (2 levels) in <top (required)>'

RSpec Config (Sentry related)

require "sentry/test_helper"

RSpec.configure do |config|
  config.include Sentry::TestHelper
  config.before { setup_sentry_test }
  config.after { teardown_sentry_test }
end

Workaround

As a workaround, we just disabled session tracking:

Sentry.init do |config|
  # ...

  # See: https://github.com/getsentry/sentry-ruby/pull/2337
  config.excluded_exceptions << "Sidekiq::JobRetry::Handled"

  # See: https://github.com/getsentry/sentry-ruby/pull/2396
  config.auto_session_tracking = false

  # ...
end

Resolves: #2378

ixti · 2024-09-02T16:23:54Z

We tried and it still fails:

require "sentry/test_helper"

RSpec.configure do |config|
  config.include Sentry::TestHelper

  config.before do
    setup_sentry_test { _1.auto_session_tracking = true }
  end

  config.after { teardown_sentry_test }
end

st0012 · 2024-09-15T11:52:32Z

Thanks for reporting the issue. It does look very puzzling as the only method that could nullify the session flusher is Sentry.close. Can you do a quick search to see if it's called anywhere in the test suite or codebase?

MrSerth · 2024-10-10T18:48:57Z

I am experiencing the same issue on production and hence reported #2378. Currently, the issue appears rather frequent for us, but not for each request:

Is there any chance I could help to get this merged and released? Without a fix, each occurrence ends up with a 500 Internal Server Error and hides actually errors. I would rather miss a session tracing than having those errors.

In our app, we never call Sentry.close ourselves.

ixti · 2024-10-18T01:32:52Z

Thanks for reporting the issue. It does look very puzzling as the only method that could nullify the session flusher is Sentry.close. Can you do a quick search to see if it's called anywhere in the test suite or codebase?

We don't call Sentry.close anywhere.

solnic · 2024-10-18T08:25:09Z

Could you grab sentry from solnic/make-closing-thread-safe branch and see if the crash is gone?

MrSerth · 2024-10-19T19:50:30Z

Could you grab sentry from solnic/make-closing-thread-safe branch and see if the crash is gone?

I tried the branch, but since we modified the codebase (where this issue normally occurred) a lot recently, I wasn't able to confirm the fix is working. Sorry for not being able to help out here. Maybe it's still valid to merge this PR using the safe navigation operator?

ixti · 2024-10-27T01:15:03Z

We also took a workaround way by disabling session tracking completely. And even if we go back, the bug is pretty sporadic, to being able to tell if the patch in solnic/make-closing-thread-safe fixes the bug or no.

solnic · 2024-10-28T07:07:56Z

Thanks folks. Would it be possible for you to disable your workarounds after we release a new version and see if it helped. The proposed fix here comes with a risk that it will silence actual failures where the session_flusher should really be there. It's kinda hard to tell which option would be worse but given that the fix addresses an edge case by making a change that may result in breaking more common cases (an actual misconfiguration of Sentry), then it's probably better not to apply the fix.

MrSerth · 2024-10-28T08:23:58Z

As written above, I already tested the branch and partially reverted some of the code changes I considered to have the most impact on this issue.

While I understand your concern, this issue (and especially the one discussed in #2428) may hide actually bugs from our code base as Sentry customers -- that happened at least for us. We would normally trust in the Sentry error reporting, but when this bug occurs, we lack any notification and insights on actual defects of our software. Hence, from our perspective, it is far less critical to miss some sessions than to miss the actual bug that occurred.

solnic · 2024-10-28T16:25:14Z

As written above, I already tested the branch and partially reverted some of the code changes I considered to have the most impact on this issue.

Gotcha, thank you!

While I understand your concern, this issue (and especially the one discussed in #2428) may hide actually bugs from our code base as Sentry customers -- that happened at least for us. We would normally trust in the Sentry error reporting, but when this bug occurs, we lack any notification and insights on actual defects of our software. Hence, from our perspective, it is far less critical to miss some sessions than to miss the actual bug that occurred.

Alright, given that Hub is going away eventually (see #1495 (comment)) we can just rely on the workarounds here and in your PR for the time being. Thanks for all your input and help with this btw!

solnic · 2024-10-28T16:25:51Z

sentry-ruby/lib/sentry/hub.rb

@@ -248,7 +248,7 @@ def end_session

      return unless session
      session.close
-      Sentry.session_flusher.add_session(session)
+      Sentry.session_flusher&.add_session(session)


Could you add a comment pointing to the related issue so that it's clear why we're doing this? 🙏🏻

fix: Safe-navigate to session flusher

666db39

solnic mentioned this pull request Oct 18, 2024

Make Sentry.{close,get_main_hub} thread-safe #2436

Merged

solnic mentioned this pull request Oct 28, 2024

RescuedExceptionInterceptor: Handle empty configuration #2428

Merged

solnic reviewed Oct 28, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: Safe-navigate to session flusher #2396

fix: Safe-navigate to session flusher #2396

ixti commented Sep 2, 2024 •

edited

Loading

ixti commented Sep 2, 2024 •

edited

Loading

st0012 commented Sep 15, 2024 •

edited

Loading

MrSerth commented Oct 10, 2024

ixti commented Oct 18, 2024

solnic commented Oct 18, 2024

MrSerth commented Oct 19, 2024

ixti commented Oct 27, 2024

solnic commented Oct 28, 2024

MrSerth commented Oct 28, 2024

solnic commented Oct 28, 2024

solnic Oct 28, 2024

fix: Safe-navigate to session flusher #2396

Are you sure you want to change the base?

fix: Safe-navigate to session flusher #2396

Conversation

ixti commented Sep 2, 2024 • edited Loading

Example failure

RSpec Config (Sentry related)

Workaround

ixti commented Sep 2, 2024 • edited Loading

st0012 commented Sep 15, 2024 • edited Loading

MrSerth commented Oct 10, 2024

ixti commented Oct 18, 2024

solnic commented Oct 18, 2024

MrSerth commented Oct 19, 2024

ixti commented Oct 27, 2024

solnic commented Oct 28, 2024

MrSerth commented Oct 28, 2024

solnic commented Oct 28, 2024

solnic Oct 28, 2024

Choose a reason for hiding this comment

ixti commented Sep 2, 2024 •

edited

Loading

ixti commented Sep 2, 2024 •

edited

Loading

st0012 commented Sep 15, 2024 •

edited

Loading