diff --git a/.github/workflows/sentry_sidekiq_test.yml b/.github/workflows/sentry_sidekiq_test.yml index 4db2784f7..0669d1293 100644 --- a/.github/workflows/sentry_sidekiq_test.yml +++ b/.github/workflows/sentry_sidekiq_test.yml @@ -52,14 +52,14 @@ jobs: sidekiq_version: 7.0 - ruby_version: "3.2" sidekiq_version: 7.0 - options: - rubyopt: "--enable-frozen-string-literal --debug=frozen-string-literal" - ruby_version: "3.2" - sidekiq_version: 8.0.0.beta1 + sidekiq_version: 8.0.0 - ruby_version: "3.3" - sidekiq_version: 8.0.0.beta1 + sidekiq_version: 8.0.0 - ruby_version: "3.4" - sidekiq_version: 8.0.0.beta1 + sidekiq_version: 8.0.0 + options: + rubyopt: "--enable-frozen-string-literal --debug=frozen-string-literal" exclude: - ruby_version: head - ruby_version: jruby diff --git a/CHANGELOG.md b/CHANGELOG.md index 4473f9c8a..8b0bcb716 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ - Fix breadcrumb serialization error message to be an object ([#2584](https://github.com/getsentry/sentry-ruby/pull/2584)) - Fixes [#2478](https://github.com/getsentry/sentry-ruby/issues/2478) - Fix compatibility issues with sidekiq-cron 2.2.0 ([#2591](https://github.com/getsentry/sentry-ruby/pull/2591)) +- Update sentry-sidekiq to work correctly with Sidekiq 8.0 and its new timestamp format ([#2570](https://github.com/getsentry/sentry-ruby/pull/2570)) ### Internal diff --git a/sentry-sidekiq/Gemfile b/sentry-sidekiq/Gemfile index aaacbf5a3..d2b5ad780 100644 --- a/sentry-sidekiq/Gemfile +++ b/sentry-sidekiq/Gemfile @@ -28,7 +28,12 @@ end if sidekiq_version == "main" || RUBY_VERSION.to_f >= 2.7 && sidekiq_version >= Gem::Version.new("6.0") gem "sidekiq-cron" - gem "sidekiq-scheduler" + + if sidekiq_version == "main" || sidekiq_version >= Gem::Version.new("8.0") + gem "sidekiq-scheduler", "~> 6.0.0.beta" + else + gem "sidekiq-scheduler", "~> 5.0.0" + end end gem "rails", "> 5.0.0" diff --git a/sentry-sidekiq/lib/sentry/sidekiq/sentry_context_middleware.rb b/sentry-sidekiq/lib/sentry/sidekiq/sentry_context_middleware.rb index bae97b9e6..c1fb4b6b1 100644 --- a/sentry-sidekiq/lib/sentry/sidekiq/sentry_context_middleware.rb +++ b/sentry-sidekiq/lib/sentry/sidekiq/sentry_context_middleware.rb @@ -13,6 +13,20 @@ def set_span_data(span, id:, queue:, latency: nil, retry_count: nil) span.set_data(Span::DataConventions::MESSAGING_MESSAGE_RECEIVE_LATENCY, latency) if latency span.set_data(Span::DataConventions::MESSAGING_MESSAGE_RETRY_COUNT, retry_count) if retry_count end + + if ::Gem::Version.new(::Sidekiq::VERSION) >= ::Gem::Version.new("8.0.0") + def calculate_latency(job) + now_in_ms - job["enqueued_at"] if job["enqueued_at"] + end + else + def calculate_latency(job) + ((Time.now.to_f - job["enqueued_at"]) * 1000).round if job["enqueued_at"] + end + end + + def now_in_ms + ::Process.clock_gettime(::Process::CLOCK_REALTIME, :millisecond) + end end class SentryContextServerMiddleware @@ -40,7 +54,8 @@ def call(worker, job, queue) if transaction scope.set_span(transaction) - latency = ((Time.now.to_f - job["enqueued_at"]) * 1000).to_i if job["enqueued_at"] + latency = calculate_latency(job) + set_span_data( transaction, id: job["jid"], diff --git a/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb b/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb index 5e144bf9a..d1e835d6b 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb +++ b/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb @@ -11,20 +11,38 @@ Sentry.get_current_client.transport end - let(:context) do - { - "args" => [true, true], - "class" => "HardWorker", - "created_at" => 1_474_922_824.910579, - "enqueued_at" => 1_474_922_824.910665, - "error_class" => "RuntimeError", - "error_message" => "a wild exception appeared", - "failed_at" => 1_474_922_825.158953, - "jid" => "701ed9cfa51c84a763d56bc4", - "queue" => "default", - "retry" => true, - "retry_count" => 0 - } + if WITH_SIDEKIQ_8 + let(:context) do + { + "args" => [true, true], + "class" => "HardWorker", + "created_at" => 1_474_922_824_910, + "enqueued_at" => 1_474_922_824_910, + "error_class" => "RuntimeError", + "error_message" => "a wild exception appeared", + "failed_at" => 1_474_922_825_158, + "jid" => "701ed9cfa51c84a763d56bc4", + "queue" => "default", + "retry" => true, + "retry_count" => 0 + } + end + else + let(:context) do + { + "args" => [true, true], + "class" => "HardWorker", + "created_at" => 1_474_922_824.910579, + "enqueued_at" => 1_474_922_824.910665, + "error_class" => "RuntimeError", + "error_message" => "a wild exception appeared", + "failed_at" => 1_474_922_825.158953, + "jid" => "701ed9cfa51c84a763d56bc4", + "queue" => "default", + "retry" => true, + "retry_count" => 0 + } + end end let(:processor) do diff --git a/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb b/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb index b12a786c1..7f6ea7e95 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb +++ b/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb @@ -68,36 +68,29 @@ end context "span data for Queues module" do - it "adds a queue.process transaction with correct data" do - Timecop.freeze do - execute_worker(processor, HappyWorker) - end - - expect(transport.events.count).to eq(1) + def timecop_delay + Time.now + expected_latency / 1000 + end - transaction = transport.events[0] - expect(transaction).not_to be_nil - expect(transaction.spans.count).to eq(0) - expect(transaction.contexts[:trace][:data]['messaging.message.id']).to eq('123123') # Default defined in #execute_worker - expect(transaction.contexts[:trace][:data]['messaging.destination.name']).to eq('default') - expect(transaction.contexts[:trace][:data]['messaging.message.receive.latency']).to eq(0) - expect(transaction.contexts[:trace][:data]['messaging.message.retry.count']).to eq(0) + let(:expected_latency) do + 86400000 end - it "adds a queue.process transaction with correct latency data" do - Timecop.freeze do - execute_worker(processor, HappyWorker, jid: '123456', timecop_delay: Time.now + 86400) - end + it "adds a queue.process transaction with correct data" do + execute_worker(processor, HappyWorker, jid: '123456', timecop_delay: timecop_delay) expect(transport.events.count).to eq(1) transaction = transport.events[0] + trace = transaction.contexts[:trace] + expect(transaction).not_to be_nil expect(transaction.spans.count).to eq(0) - expect(transaction.contexts[:trace][:data]['messaging.message.id']).to eq('123456') # Explicitly set above. - expect(transaction.contexts[:trace][:data]['messaging.destination.name']).to eq('default') - expect(transaction.contexts[:trace][:data]['messaging.message.receive.latency']).to eq(86400000) - expect(transaction.contexts[:trace][:data]['messaging.message.retry.count']).to eq(0) + + expect(trace[:data]['messaging.message.id']).to eq('123456') + expect(trace[:data]['messaging.destination.name']).to eq('default') + expect(trace[:data]['messaging.message.retry.count']).to eq(0) + expect(trace[:data]['messaging.message.receive.latency']).to eq(expected_latency) end if MIN_SIDEKIQ_6 diff --git a/sentry-sidekiq/spec/spec_helper.rb b/sentry-sidekiq/spec/spec_helper.rb index 677e0544f..5a8877f5a 100644 --- a/sentry-sidekiq/spec/spec_helper.rb +++ b/sentry-sidekiq/spec/spec_helper.rb @@ -11,6 +11,7 @@ MIN_SIDEKIQ_6 = Gem::Version.new(Sidekiq::VERSION) >= Gem::Version.new("6.0") WITH_SIDEKIQ_7 = Gem::Version.new(Sidekiq::VERSION) >= Gem::Version.new("7.0") +WITH_SIDEKIQ_8 = Gem::Version.new(Sidekiq::VERSION) >= Gem::Version.new("8.0.0") WITH_SIDEKIQ_6 = MIN_SIDEKIQ_6 && !WITH_SIDEKIQ_7 require "sidekiq/embedded" if WITH_SIDEKIQ_7 @@ -56,6 +57,14 @@ c.syntax = :expect end + config.before :suite do + puts "\n" + puts "*" * 100 + puts "Running with Sidekiq #{Sidekiq::VERSION}" + puts "*" * 100 + puts "\n" + end + config.before :each do # Make sure we reset the env in case something leaks in ENV.delete('SENTRY_DSN') @@ -273,6 +282,10 @@ def sidekiq_config(opts) WITH_SIDEKIQ_7 ? ::Sidekiq::Config.new(opts) : SidekiqConfigMock.new(opts) end +def now_in_ms + ::Process.clock_gettime(::Process::CLOCK_REALTIME, :millisecond) +end + def execute_worker(processor, klass, **options) klass_options = klass.sidekiq_options_hash || {} # for Ruby < 2.6 @@ -283,12 +296,40 @@ def execute_worker(processor, klass, **options) jid = options.delete(:jid) || "123123" timecop_delay = options.delete(:timecop_delay) - msg = Sidekiq.dump_json(created_at: Time.now.to_f, enqueued_at: Time.now.to_f, jid: jid, class: klass, args: [], **options) - Timecop.freeze(timecop_delay) if timecop_delay + timestamps = if WITH_SIDEKIQ_8 + current_time_ms = now_in_ms + { + created_at: current_time_ms, + enqueued_at: current_time_ms + } + else + { + created_at: Time.now.to_f, + enqueued_at: Time.now.to_f + } + end + + msg = Sidekiq.dump_json( + jid: jid, + class: klass, + args: [], + **timestamps, + **options + ) + + if timecop_delay + Timecop.mock_process_clock = true + Timecop.freeze(timecop_delay) + end + work = Sidekiq::BasicFetch::UnitOfWork.new('queue:default', msg) + process_work(processor, work) ensure - Timecop.return if timecop_delay + if timecop_delay + Timecop.return + Timecop.mock_process_clock = false + end end def process_work(processor, work)