Sidekiq 8.0 updates (#2570)

* Update CHANGELOG

* [sidekiq] display Sidekiq version before suite

* [sidekiq] use sidekiq-scheduler 6.0.0.beta

* [sidekiq] run tests against released 8.0.0

* [sidekiq] fix handling of latency under 8.0

* [sidekiq] remove redundant spec

Author: solnic

.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

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
 

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"

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"],

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

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

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)