From 1156faaa32a7f190d7018e23a8e64eb8b5af1cac Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Fri, 28 Feb 2025 15:44:38 +0000 Subject: [PATCH 1/6] Update CHANGELOG --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) 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 From eace374a720428cb19fb9467ab8db1ae5cd4461a Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 15 Apr 2025 08:34:43 +0000 Subject: [PATCH 2/6] [sidekiq] display Sidekiq version before suite --- sentry-sidekiq/spec/spec_helper.rb | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/sentry-sidekiq/spec/spec_helper.rb b/sentry-sidekiq/spec/spec_helper.rb index 677e0544f..7cc95c9a5 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') From 4f8a6e664f3e48fbb3e7d1b9f1bbbfe67ad704b4 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 15 Apr 2025 08:14:37 +0000 Subject: [PATCH 3/6] [sidekiq] use sidekiq-scheduler 6.0.0.beta --- sentry-sidekiq/Gemfile | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) 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" From c04d3bed19db9c3d5d746f0acff2274f614a9b4c Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 15 Apr 2025 08:19:08 +0000 Subject: [PATCH 4/6] [sidekiq] run tests against released 8.0.0 --- .github/workflows/sentry_sidekiq_test.yml | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) 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 From c26d55cd1349af865ef82c412f315c5213cdc9e9 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 15 Apr 2025 08:34:49 +0000 Subject: [PATCH 5/6] [sidekiq] fix handling of latency under 8.0 --- .../sidekiq/sentry_context_middleware.rb | 17 ++++++- .../spec/sentry/sidekiq/error_handler_spec.rb | 46 +++++++++++++------ .../sidekiq/sentry_context_middleware_spec.rb | 34 +++++++++----- sentry-sidekiq/spec/spec_helper.rb | 38 +++++++++++++-- 4 files changed, 106 insertions(+), 29 deletions(-) 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..9bbf39ea3 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb +++ b/sentry-sidekiq/spec/sentry/sidekiq/sentry_context_middleware_spec.rb @@ -76,28 +76,40 @@ 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('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) + + expect(trace[:data]['messaging.message.id']).to eq('123123') + 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 be >= 0 + end + + def timecop_delay + Time.now + expected_latency / 1000 + end + + 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 + 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 7cc95c9a5..5a8877f5a 100644 --- a/sentry-sidekiq/spec/spec_helper.rb +++ b/sentry-sidekiq/spec/spec_helper.rb @@ -282,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 @@ -292,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) From a702652ce6dcd9cced86c946ff3dced16967d8cf Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 29 Apr 2025 13:06:47 +0000 Subject: [PATCH 6/6] [sidekiq] remove redundant spec --- .../sidekiq/sentry_context_middleware_spec.rb | 21 +------------------ 1 file changed, 1 insertion(+), 20 deletions(-) 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 9bbf39ea3..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,25 +68,6 @@ 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) - - transaction = transport.events[0] - trace = transaction.contexts[:trace] - - expect(transaction).not_to be_nil - expect(transaction.spans.count).to eq(0) - - expect(trace[:data]['messaging.message.id']).to eq('123123') - 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 be >= 0 - end - def timecop_delay Time.now + expected_latency / 1000 end @@ -95,7 +76,7 @@ def timecop_delay 86400000 end - it "adds a queue.process transaction with correct latency data" do + 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)