diff --git a/.github/workflows/sentry_sidekiq_test.yml b/.github/workflows/sentry_sidekiq_test.yml index 861b57254..d744a4762 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-head diff --git a/CHANGELOG.md b/CHANGELOG.md index 276e755c1..c2ae64132 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,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 ccc3b3ce2..570ac2765 100644 --- a/sentry-sidekiq/Gemfile +++ b/sentry-sidekiq/Gemfile @@ -15,20 +15,25 @@ gem "sentry-rails", path: "../sentry-rails" # loofah changed the required ruby version in a patch so we need to explicitly pin it gem "loofah", "2.20.0" if RUBY_VERSION.to_f < 2.5 +DEFAULT_SIDEKIQ_VERSION = "8.0.0" + if ENV["SIDEKIQ_MAIN"] gem "sidekiq", github: "sidekiq/sidekiq", branch: "main" sidekiq_version = "main" else - sidekiq_version = ENV["SIDEKIQ_VERSION"] - sidekiq_version = "7.0" if sidekiq_version.nil? - sidekiq_version = Gem::Version.new(sidekiq_version) + sidekiq_version = Gem::Version.new(ENV.fetch("SIDEKIQ_VERSION", DEFAULT_SIDEKIQ_VERSION)) gem "sidekiq", "~> #{sidekiq_version}" 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..a4bf13d5f 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).to_i 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..b2c035e28 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb +++ b/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb @@ -11,20 +11,33 @@ Sentry.get_current_client.transport end + let(:timestamps) do + if WITH_SIDEKIQ_8 + { + "created_at" => 1_474_922_824_910, + "enqueued_at" => 1_474_922_824_910, + "failed_at" => 1_474_922_825_158 + } + else + { + "created_at" => 1_474_922_824.910579, + "enqueued_at" => 1_474_922_824.910665, + "failed_at" => 1_474_922_825.158953 + } + end + 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 - } + }.merge(timestamps) 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..ce9157304 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 - 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) + def timecop_delay + if WITH_SIDEKIQ_8 + Time.now + 1 + else + Time.now + 1000 end + end + + it "adds a queue.process transaction with correct latency 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(1000) end if MIN_SIDEKIQ_6 diff --git a/sentry-sidekiq/spec/spec_helper.rb b/sentry-sidekiq/spec/spec_helper.rb index 677e0544f..fa803d5d4 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)