add report_after_job_retries support for ActiveJob

[modosc]

Description

this pr adds report_after_job_retries support to ActiveJob (configured via config.rails.active_job_report_after_job_retries).

the easiest way to do this would have been to use retry_on in the base ActiveJob class (similar to here) but that's difficult to do properly which is (i think) why the current ActiveJob integration doesn't do it.

instead we can take advantage of the retry_stopped.active_job notification that's published when a job runs out of retries. this makes our setup a single call to ActiveSupport::Notifications.subscribe.

fixes #2499

[codecov]

Codecov Report

Attention: Patch coverage is 65.00000% with 7 lines in your changes missing coverage. Please review.

Project coverage is 96.99%. Comparing base (a1d2941) to head (f8a24b2).

Files with missing lines	Patch %	Lines
sentry-rails/lib/sentry/rails/active_job.rb	53.33%	7 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #2500      +/-   ##
==========================================
- Coverage   98.16%   96.99%   -1.18%     
==========================================
  Files         128      126       -2     
  Lines        4847     4787      -60     
==========================================
- Hits         4758     4643     -115     
- Misses         89      144      +55     

Components	Coverage Δ
sentry-ruby	98.57% <ø> (ø)
sentry-rails	87.26% <65.00%> (-9.81%)	⬇️
sentry-sidekiq	97.09% <ø> (ø)
sentry-resque	92.85% <ø> (ø)
sentry-delayed_job	95.65% <ø> (ø)
sentry-opentelemetry	99.31% <ø> (+0.68%)	⬆️

Files with missing lines	Coverage Δ
sentry-rails/lib/sentry/rails/configuration.rb	95.45% <100.00%> (-4.55%)	⬇️
sentry-rails/lib/sentry/rails/railtie.rb	87.95% <100.00%> (-10.80%)	⬇️
sentry-rails/lib/sentry/rails/active_job.rb	87.71% <53.33%> (-12.29%)	⬇️

... and 10 files with indirect coverage changes

[sl0thentr0py]

@solnic could you review and get this merged if you have time?

[solnic]

@sl0thentr0py looking into it today

[solnic]

I've been digging into this and I don't think it works as expected and the test results are misleading. The spec actually ends up with 3 errors logged and I do not understand how it happens.

I added this pp statement to the spec:

    context "when active_job_report_after_job_retries is true" do
      before do
        Sentry.configuration.rails.active_job_report_after_job_retries = true
      end

      after do
        Sentry.configuration.rails.active_job_report_after_job_retries = false
      end

      it "reports 1 exception" do
        assert_performed_jobs 3 do
          FailedJobWithRetryOn.perform_later rescue nil
        end

        pp transport.events.first.exception.values

        expect(Sentry::Rails::ActiveJobExtensions::SentryReporter)
          .to have_received(:capture_exception)
          .exactly(1).times
      end

and here's the output:

[#<Sentry::SingleExceptionInterface @type="FailedJob::TestError", @value="Boom! (FailedJob::TestError)", @module="FailedJob", @thread_id=12700, @mechanism=#<Sentry::Mechanism:0x0000ffff6340aa70 @type="rails", @handled=false>>,
 #<Sentry::SingleExceptionInterface @type="FailedJob::TestError", @value="Boom! (FailedJob::TestError)", @module="FailedJob", @thread_id=12700, @mechanism=#<Sentry::Mechanism:0x0000ffff6340aa70 @type="rails", @handled=false>>,
 #<Sentry::SingleExceptionInterface @type="FailedJob::TestError", @value="Boom! (FailedJob::TestError)", @module="FailedJob", @thread_id=12700, @mechanism=#<Sentry::Mechanism:0x0000ffff6340aa70 @type="rails", @handled=false>>]

Any ideas what is reporting these errors? It happens regardless if we use mocks or not.

[modosc]

@solnic which version of rails / ruby are you testing against? in the automated tests i see seemingly random counts in the failures:

• 64
• 127
• 111
• 60
• 33

note that i only used expect(Sentry::Rails::ActiveJobExtensions::SentryReporter) because i got similar results using expect(transport.events.size).to eq - i just assumed i was doing something else wrong.

it's also possible that the event publishing changed in between rails versions? if that's the case then i think we'd have to use the other approach i mentioned.

also fwiw i can confirm that subscribing to this event and sending an error to sentry does perform as expected in rails 8.0.1 / ruby 3.4.1 (we're using this now in production at my workplace) so it's quite possible the issue lies in the test tooling (maybe assert_performed_jobs runs in a separate thread or something)?

[solnic]

also fwiw i can confirm that subscribing to this event and sending an error to sentry does perform as expected in rails 8.0.1 / ruby 3.4.1 (we're using this now in production at my workplace) so it's quite possible the issue lies in the test tooling (maybe assert_performed_jobs runs in a separate thread or something)?

It fails when I run both scenarios, passes when I run individually:

     reports 3 exceptions
    when active_job_report_after_job_retries is true
      reports 1 exception (FAILED - 1)

Failures:

  1) ActiveJob integration active_job_report_after_job_retries when active_job_report_after_job_retries is true reports 1 exception
     Failure/Error:
       expect(Sentry::Rails::ActiveJobExtensions::SentryReporter)
         .to have_received(:capture_exception)
         .exactly(1).times
     
       (Sentry::Rails::ActiveJobExtensions::SentryReporter (class)).capture_exception(*(any args))
           expected: 1 time with any arguments
           received: 2 times with any arguments
     # ./spec/sentry/rails/activejob_spec.rb:425:in `block (4 levels) in <top (required)>'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'

Finished in 0.28003 seconds (files took 0.76855 seconds to load)
2 examples, 1 failure

Failed examples:

rspec ./spec/sentry/rails/activejob_spec.rb:420 # ActiveJob integration active_job_report_after_job_retries when active_job_report_after_job_retries is true reports 1 exception

This is latest rails and latest ruby.

[solnic]

This is SO strange. When I run all tests from that file I get this:

       (Sentry::Rails::ActiveJobExtensions::SentryReporter (class)).capture_exception(*(any args))
           expected: 1 time with any arguments
           received: 23 times with any arguments

So it's like we get rspec's mocked calls count from all tests, and they just leak between the spec runs 🙈