fix: handle time now being in milliseconds rather than float in seconds

Author: dmathieu

instrumentation/sidekiq/lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb

@@ -31,11 +31,13 @@ def call(_worker, msg, _queue)
                           end
 
               extracted_context = OpenTelemetry.propagation.extract(msg)
+              created_at = time_from_timestamp(msg['created_at'])
+              enqueued_at = time_from_timestamp(msg['created_at'])
               OpenTelemetry::Context.with_current(extracted_context) do
                 if instrumentation_config[:propagation_style] == :child
                   tracer.in_span(span_name, attributes: attributes, kind: :consumer) do |span|
-                    span.add_event('created_at', timestamp: msg['created_at'])
-                    span.add_event('enqueued_at', timestamp: msg['enqueued_at'])
+                    span.add_event('created_at', timestamp: created_at)
+                    span.add_event('enqueued_at', timestamp: enqueued_at)
                     yield
                   end
                 else
@@ -44,8 +46,8 @@ def call(_worker, msg, _queue)
                   links << OpenTelemetry::Trace::Link.new(span_context) if instrumentation_config[:propagation_style] == :link && span_context.valid?
                   span = tracer.start_root_span(span_name, attributes: attributes, links: links, kind: :consumer)
                   OpenTelemetry::Trace.with_span(span) do
-                    span.add_event('created_at', timestamp: msg['created_at'])
-                    span.add_event('enqueued_at', timestamp: msg['enqueued_at'])
+                    span.add_event('created_at', timestamp: created_at)
+                    span.add_event('enqueued_at', timestamp: enqueued_at)
                     yield
                   rescue Exception => e # rubocop:disable Lint/RescueException
                     span.record_exception(e)
@@ -67,6 +69,15 @@ def instrumentation_config
             def tracer
               Sidekiq::Instrumentation.instance.tracer
             end
+
+            def time_from_timestamp(timestamp)
+              if timestamp.is_a?(Float)
+                # old format, timestamps were stored as fractional seconds since the epoch
+                timestamp
+              else
+                timestamp / 1000
+              end
+            end
           end
         end
       end

instrumentation/sidekiq/test/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware_test.rb

@@ -45,8 +45,14 @@
       _(job_span.attributes['messaging.operation']).must_equal 'process'
       _(job_span.attributes['peer.service']).must_be_nil
       _(job_span.events.size).must_equal(2)
-      _(job_span.events[0].name).must_equal('created_at')
-      _(job_span.events[1].name).must_equal('enqueued_at')
+
+      created_event = job_span.events[0]
+      _(created_event.name).must_equal('created_at')
+      _(created_event.timestamp.digits.count).must_equal(19)
+
+      enqueued_event = job_span.events[1]
+      _(enqueued_event.name).must_equal('enqueued_at')
+      _(enqueued_event.timestamp.digits.count).must_equal(19)
     end
 
     it 'traces when enqueued with Active Job' do