Avoid injecting tracing timestamp to all ActiveSupport instrument eve…

…nts (#1576)

* Only inject tracing timestamp to the events SDK subscribes to

* Re-structure breadcrumb specs

* Make sure subscribed tracing events are cleared after each tests

* Update changelog

CHANGELOG.md

@@ -1,6 +1,8 @@
 ## Unreleased
 
 - Avoid leaking tracing timestamp to breadcrumbs [#1575](https://github.com/getsentry/sentry-ruby/pull/1575)
+- Avoid injecting tracing timestamp to all ActiveSupport instrument events [#1576](https://github.com/getsentry/sentry-ruby/pull/1576)
+  - Fixes [#1574](https://github.com/getsentry/sentry-ruby/issues/1574)
 
 ## 4.7.2
 

sentry-rails/lib/sentry/rails/tracing.rb

@@ -11,11 +11,18 @@ def self.subscribers
         @subscribers
       end
 
+      def self.subscribed_tracing_events
+        @subscribed_tracing_events ||= []
+      end
+
       def self.subscribe_tracing_events
         # need to avoid duplicated subscription
         return if @subscribed
 
-        subscribers.each(&:subscribe!)
+        subscribers.each do |subscriber|
+          subscriber.subscribe!
+          subscribed_tracing_events << subscriber::EVENT_NAME
+        end
 
         @subscribed = true
       end
@@ -24,6 +31,7 @@ def self.unsubscribe_tracing_events
         return unless @subscribed
 
         subscribers.each(&:unsubscribe!)
+        subscribed_tracing_events.clear
 
         @subscribed = false
       end
@@ -37,9 +45,10 @@ def self.patch_active_support_notifications
 
         SentryNotificationExtension.module_eval do
           def instrument(name, payload = {}, &block)
-            is_public_event = name[0] != "!"
-
-            payload[START_TIMESTAMP_NAME] = Time.now.utc.to_f if is_public_event
+            # only inject timestamp to the events the SDK subscribes to
+            if Tracing.subscribed_tracing_events.include?(name)
+              payload[START_TIMESTAMP_NAME] = Time.now.utc.to_f if name[0] != "!" && payload.is_a?(Hash)
+            end
 
             super(name, payload, &block)
           end

sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_breadcrumbs_spec.rb → sentry-rails/spec/sentry/rails/breadcrumbs/active_support_logger_spec.rb

@@ -1,22 +1,15 @@
 require "spec_helper"
 
-
-RSpec.describe "Sentry::Breadcrumbs::MonotonicActiveSupportLogger", type: :request do
-  before do
-    make_basic_app do |sentry_config|
-      sentry_config.breadcrumbs_logger = [:monotonic_active_support_logger]
-      sentry_config.traces_sample_rate = 1.0
-    end
-  end
-
+RSpec.describe "Sentry::Breadcrumbs::ActiveSupportLogger", type: :request do
   after do
-    require 'sentry/rails/breadcrumb/monotonic_active_support_logger'
-    Sentry::Rails::Breadcrumb::MonotonicActiveSupportLogger.detach
+    require 'sentry/rails/breadcrumb/active_support_logger'
+    Sentry::Rails::Breadcrumb::ActiveSupportLogger.detach
     # even though we cleanup breadcrumbs in the rack middleware
-    # Breadcrumbs::MonotonicActiveSupportLogger subscribes to "every" instrumentation
+    # Breadcrumbs::ActiveSupportLogger subscribes to "every" instrumentation
     # so it'll create other instrumentations "after" the request is finished
     # and we should clear those as well
     Sentry.get_current_scope.clear_breadcrumbs
+    transport.events = []
   end
 
   let(:transport) do
@@ -31,20 +24,13 @@
     transport.events.first.to_json_compatible
   end
 
-  after do
-    transport.events = []
-  end
-
-  context "given a Rails version < 6.1", skip: Rails.version.to_f >= 6.1 do
-    it "does not run instrumentation" do
-      get "/exception"
-
-      breadcrumbs = event.dig("breadcrumbs", "values")
-      expect(breadcrumbs.count).to be_zero
+  context "without tracing" do
+    before do
+      make_basic_app do |sentry_config|
+        sentry_config.breadcrumbs_logger = [:active_support_logger]
+      end
     end
-  end
 
-  context "given a Rails version >= 6.1", skip: Rails.version.to_f <= 6.1 do
     it "captures correct data of exception requests" do
       get "/exception"
 
@@ -67,6 +53,35 @@
       expect(breadcrumb["data"].keys).not_to include("response")
     end
 
+    it "ignores exception data" do
+      get "/view_exception"
+
+      expect(event.dig("breadcrumbs", "values", -1, "data").keys).not_to include("exception")
+      expect(event.dig("breadcrumbs", "values", -1, "data").keys).not_to include("exception_object")
+    end
+
+    it "ignores events that doesn't have a started timestamp" do
+      expect do
+        ActiveSupport::Notifications.publish "foo", Object.new
+      end.not_to raise_error
+
+      expect(breadcrumb_buffer.count).to be_zero
+    end
+  end
+
+  context "with tracing" do
+    before do
+      make_basic_app do |sentry_config|
+        sentry_config.breadcrumbs_logger = [:active_support_logger]
+        sentry_config.traces_sample_rate = 1.0
+      end
+    end
+
+    after do
+      Sentry::Rails::Tracing.unsubscribe_tracing_events
+      Sentry::Rails::Tracing.remove_active_support_notifications_patch
+    end
+
     it "captures correct request data of normal requests" do
       p = Post.create!
 
@@ -89,19 +104,18 @@
       expect(breadcrumb["data"].keys).not_to include("response")
     end
 
-    it "ignores exception data" do
-      get "/view_exception"
+    it "doesn't add internal start timestamp payload to breadcrumbs data" do
+      p = Post.create!
 
-      expect(event.dig("breadcrumbs", "values", -1, "data").keys).not_to include("exception")
-      expect(event.dig("breadcrumbs", "values", -1, "data").keys).not_to include("exception_object")
-    end
+      get "/posts/#{p.id}"
 
-    it "ignores events that doesn't have a float as started attributes" do
-      expect do
-        ActiveSupport::Notifications.publish "foo", Time.now
-      end.not_to raise_error
+      expect(transport.events.count).to eq(1)
 
-      expect(breadcrumb_buffer.count).to be_zero
+      transaction = transport.events.last.to_hash
+      breadcrumbs = transaction[:breadcrumbs][:values]
+      process_action_crumb = breadcrumbs.last
+      expect(process_action_crumb[:category]).to eq("process_action.action_controller")
+      expect(process_action_crumb[:data].has_key?(Sentry::Rails::Tracing::START_TIMESTAMP_NAME)).to eq(false)
     end
   end
 end