fix: ensure instrumentation durations are unique during threaded executions (#658)

Author: rabidpraxis

lib/honeybadger/backend/test.rb

@@ -42,13 +42,17 @@ def check_ins
         self.class.check_ins
       end
 
+      def events
+        self.class.events
+      end
+
       def notify(feature, payload)
         notifications[feature] << payload
         super
       end
 
       def event(payload)
-        events << payload
+        events.concat(payload.dup)
         super
       end
 

lib/honeybadger/notification_subscriber.rb

@@ -6,17 +6,16 @@ class NotificationSubscriber
     include Honeybadger::InstrumentationHelper
 
     def start(name, id, payload)
-      @start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
+      payload[:_start_time] = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
     end
 
     def finish(name, id, payload)
-      @finish_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
-
+      finish_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
       return unless process?(name, payload)
 
       payload = {
         instrumenter_id: id,
-        duration: ((@finish_time - @start_time) * 1000).round(2)
+        duration: ((finish_time - payload.delete(:_start_time)) * 1000).round(2)
       }.merge(format_payload(payload).compact)
 
       record(name, payload)

spec/integration/rails/notification_subscriber_spec.rb

@@ -0,0 +1,43 @@
+require_relative "../rails_helper"
+require "honeybadger/notification_subscriber"
+
+class TestSubscriber < Honeybadger::NotificationSubscriber; end
+
+describe "Rails Insights Notification Subscribers", if: RAILS_PRESENT, type: :request do
+  load_rails_hooks(self)
+
+  before do
+    Honeybadger.config[:"insights.enabled"] = true
+    Honeybadger.config[:"events.batch_size"] = 0
+
+    Honeybadger::Backend::Test.events.clear
+  end
+
+  it "records correct durations for concurrent notifications" do
+    mutex, sequence = Mutex.new, 1
+    allow(Process).to receive(:clock_gettime).with(Process::CLOCK_MONOTONIC) do
+      if caller_locations.any? { |loc| loc.base_label == "finish" }
+        10
+      else
+        mutex.synchronize { sequence += 1 }
+      end
+    end
+
+    ActiveSupport::Notifications.subscribe("test.timing", TestSubscriber.new)
+
+    # Create multiple threads that will fire notifications
+    threads = 5.times.map do
+      Thread.new do
+        ActiveSupport::Notifications.instrument("test.timing") do
+          sleep(0.1)
+        end
+      end
+    end
+
+    threads.each(&:join)
+    # Wait for all events to be processed
+    sleep(0.2)
+
+    expect(Honeybadger::Backend::Test.events.map { |e| e[:duration] }.uniq.length).to eq(5)
+  end
+end