From 3e8a0146573f464299ed8a0b7f9c43388d418a1d Mon Sep 17 00:00:00 2001 From: st0012 Date: Sat, 18 Sep 2021 10:35:06 +0800 Subject: [PATCH 1/4] Only inject tracing timestamp to the events SDK subscribes to --- sentry-rails/lib/sentry/rails/tracing.rb | 17 +++++++++++++---- .../active_support_breadcrumbs_spec.rb | 4 +++- sentry-rails/spec/sentry/rails/tracing_spec.rb | 9 +++++++++ sentry-rails/spec/support/test_rails_app/app.rb | 13 +++++++++++++ 4 files changed, 38 insertions(+), 5 deletions(-) diff --git a/sentry-rails/lib/sentry/rails/tracing.rb b/sentry-rails/lib/sentry/rails/tracing.rb index e4bf52b7a..62760e0c5 100644 --- a/sentry-rails/lib/sentry/rails/tracing.rb +++ b/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 diff --git a/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb b/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb index 93914fe31..ccda15479 100644 --- a/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb +++ b/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb @@ -103,7 +103,9 @@ transaction = transport.events.last.to_hash breadcrumbs = transaction[:breadcrumbs][:values] - expect(breadcrumbs.last[:data].has_key?(Sentry::Rails::Tracing::START_TIMESTAMP_NAME)).to eq(false) + 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 diff --git a/sentry-rails/spec/sentry/rails/tracing_spec.rb b/sentry-rails/spec/sentry/rails/tracing_spec.rb index 1225b5514..679736bd6 100644 --- a/sentry-rails/spec/sentry/rails/tracing_spec.rb +++ b/sentry-rails/spec/sentry/rails/tracing_spec.rb @@ -28,6 +28,7 @@ it "records transaction with exception" do get "/posts" + expect(response).to have_http_status(:internal_server_error) expect(transport.events.count).to eq(2) event = transport.events.first.to_hash @@ -60,6 +61,7 @@ get "/posts/#{p.id}" + expect(response).to have_http_status(:ok) expect(transport.events.count).to eq(1) transaction = transport.events.last.to_hash @@ -87,6 +89,13 @@ expect(last_span[:description]).to eq("PostsController#show") expect(last_span[:parent_span_id]).to eq(parent_span_id) end + + it "doesn't mess with custom instrumentations" do + get "/with_custom_instrumentation" + expect(response).to have_http_status(:ok) + + expect(transport.events.count).to eq(1) + end end context "with sprockets-rails" do diff --git a/sentry-rails/spec/support/test_rails_app/app.rb b/sentry-rails/spec/support/test_rails_app/app.rb index b086632a5..4f61aeeb5 100644 --- a/sentry-rails/spec/support/test_rails_app/app.rb +++ b/sentry-rails/spec/support/test_rails_app/app.rb @@ -70,6 +70,18 @@ def world render :plain => "Hello World!" end + def with_custom_instrumentation + custom_event = "custom.instrument" + ActiveSupport::Notifications.subscribe(custom_event) do |*args| + data = args[-1] + data += 1 + end + + ActiveSupport::Notifications.instrument(custom_event, 1) + + head :ok + end + def not_found raise ActionController::BadRequest end @@ -93,6 +105,7 @@ def self.name get "/view", :to => "hello#view" get "/not_found", :to => "hello#not_found" get "/world", to: "hello#world" + get "/with_custom_instrumentation", to: "hello#with_custom_instrumentation" resources :posts, only: [:index, :show] get "500", to: "hello#reporting" root :to => "hello#world" From 5d41ab010c56f9d82785618885771eafbac9ea78 Mon Sep 17 00:00:00 2001 From: st0012 Date: Sat, 18 Sep 2021 11:00:12 +0800 Subject: [PATCH 2/4] Re-structure breadcrumb specs --- .../active_support_breadcrumbs_spec.rb | 111 -------------- ..._spec.rb => active_support_logger_spec.rb} | 82 +++++----- .../monotonic_active_support_logger_spec.rb | 143 ++++++++++++++++++ 3 files changed, 191 insertions(+), 145 deletions(-) delete mode 100644 sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb rename sentry-rails/spec/sentry/rails/breadcrumbs/{monotonic_active_support_breadcrumbs_spec.rb => active_support_logger_spec.rb} (63%) create mode 100644 sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_logger_spec.rb diff --git a/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb b/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb deleted file mode 100644 index ccda15479..000000000 --- a/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_breadcrumbs_spec.rb +++ /dev/null @@ -1,111 +0,0 @@ -require "spec_helper" - -RSpec.describe "Sentry::Breadcrumbs::ActiveSupportLogger", type: :request 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 - require 'sentry/rails/breadcrumb/active_support_logger' - Sentry::Rails::Breadcrumb::ActiveSupportLogger.detach - # even though we cleanup breadcrumbs in the rack middleware - # 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 - end - - let(:transport) do - Sentry.get_current_client.transport - end - - let(:breadcrumb_buffer) do - Sentry.get_current_scope.breadcrumbs - end - - let(:event) do - transport.events.first.to_json_compatible - end - - after do - transport.events = [] - end - - it "captures correct data of exception requests" do - get "/exception" - - expect(response.status).to eq(500) - breadcrumbs = event.dig("breadcrumbs", "values") - expect(breadcrumbs.count).to eq(2) - - breadcrumb = breadcrumbs.detect { |b| b["category"] == "process_action.action_controller" } - expect(breadcrumb["data"]).to include( - { - "controller" => "HelloController", - "action" => "exception", - "params" => { "controller" => "hello", "action" => "exception" }, - "format" => "html", - "method" => "GET", "path" => "/exception", - } - ) - expect(breadcrumb["data"].keys).not_to include("headers") - expect(breadcrumb["data"].keys).not_to include("request") - expect(breadcrumb["data"].keys).not_to include("response") - end - - it "captures correct request data of normal requests" do - p = Post.create! - - get "/posts/#{p.id}" - - breadcrumbs = event.dig("breadcrumbs", "values") - - breadcrumb = breadcrumbs.detect { |b| b["category"] == "process_action.action_controller" } - expect(breadcrumb["data"]).to include( - { - "controller" => "PostsController", - "action" => "show", - "params" => { "controller" => "posts", "action" => "show", "id" => p.id.to_s }, - "format" => "html", - "method" => "GET", "path" => "/posts/#{p.id}", - } - ) - expect(breadcrumb["data"].keys).not_to include("headers") - expect(breadcrumb["data"].keys).not_to include("request") - 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 - - context "when used with tracing" do - it "doesn't add internal start timestamp payload to breadcrumbs data" do - p = Post.create! - - get "/posts/#{p.id}" - - expect(transport.events.count).to eq(1) - - 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 diff --git a/sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_breadcrumbs_spec.rb b/sentry-rails/spec/sentry/rails/breadcrumbs/active_support_logger_spec.rb similarity index 63% rename from sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_breadcrumbs_spec.rb rename to sentry-rails/spec/sentry/rails/breadcrumbs/active_support_logger_spec.rb index ee544b2d2..5a8ac0ac7 100644 --- a/sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_breadcrumbs_spec.rb +++ b/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 diff --git a/sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_logger_spec.rb b/sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_logger_spec.rb new file mode 100644 index 000000000..d578b3c8d --- /dev/null +++ b/sentry-rails/spec/sentry/rails/breadcrumbs/monotonic_active_support_logger_spec.rb @@ -0,0 +1,143 @@ +require "spec_helper" + + +RSpec.describe "Sentry::Breadcrumbs::MonotonicActiveSupportLogger", type: :request do + after do + require 'sentry/rails/breadcrumb/monotonic_active_support_logger' + Sentry::Rails::Breadcrumb::MonotonicActiveSupportLogger.detach + # even though we cleanup breadcrumbs in the rack middleware + # Breadcrumbs::MonotonicActiveSupportLogger 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 + Sentry.get_current_client.transport + end + + let(:breadcrumb_buffer) do + Sentry.get_current_scope.breadcrumbs + end + + let(:event) do + transport.events.first.to_json_compatible + end + context "without tracing" do + before do + make_basic_app do |sentry_config| + sentry_config.breadcrumbs_logger = [:monotonic_active_support_logger] + end + 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 + 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" + + expect(response.status).to eq(500) + breadcrumbs = event.dig("breadcrumbs", "values") + expect(breadcrumbs.count).to eq(2) + + breadcrumb = breadcrumbs.detect { |b| b["category"] == "process_action.action_controller" } + expect(breadcrumb["data"]).to include( + { + "controller" => "HelloController", + "action" => "exception", + "params" => { "controller" => "hello", "action" => "exception" }, + "format" => "html", + "method" => "GET", "path" => "/exception", + } + ) + expect(breadcrumb["data"].keys).not_to include("headers") + expect(breadcrumb["data"].keys).not_to include("request") + 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 float as started attributes" do + expect do + ActiveSupport::Notifications.publish "foo", Time.now + end.not_to raise_error + + expect(breadcrumb_buffer.count).to be_zero + end + end + end + + context "with tracing" 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 + + after do + Sentry::Rails::Tracing.unsubscribe_tracing_events + Sentry::Rails::Tracing.remove_active_support_notifications_patch + 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 + end + end + + context "given a Rails version >= 6.1", skip: Rails.version.to_f < 6.1 do + it "captures correct request data of normal requests" do + p = Post.create! + + get "/posts/#{p.id}" + + breadcrumbs = event.dig("breadcrumbs", "values") + + breadcrumb = breadcrumbs.detect { |b| b["category"] == "process_action.action_controller" } + expect(breadcrumb["data"]).to include( + { + "controller" => "PostsController", + "action" => "show", + "params" => { "controller" => "posts", "action" => "show", "id" => p.id.to_s }, + "format" => "html", + "method" => "GET", "path" => "/posts/#{p.id}", + } + ) + expect(breadcrumb["data"].keys).not_to include("headers") + expect(breadcrumb["data"].keys).not_to include("request") + expect(breadcrumb["data"].keys).not_to include("response") + end + + it "doesn't add internal start timestamp payload to breadcrumbs data" do + p = Post.create! + + get "/posts/#{p.id}" + + expect(transport.events.count).to eq(1) + + 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 +end From af128f57e2bb78de7e9a67fa5005e9f51343d43e Mon Sep 17 00:00:00 2001 From: st0012 Date: Sat, 18 Sep 2021 12:21:11 +0800 Subject: [PATCH 3/4] Make sure subscribed tracing events are cleared after each tests --- sentry-rails/spec/spec_helper.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/sentry-rails/spec/spec_helper.rb b/sentry-rails/spec/spec_helper.rb index d19f9257a..7c9bb9a95 100644 --- a/sentry-rails/spec/spec_helper.rb +++ b/sentry-rails/spec/spec_helper.rb @@ -42,6 +42,7 @@ config.after :each do Sentry::Rails::Tracing.unsubscribe_tracing_events + expect(Sentry::Rails::Tracing.subscribed_tracing_events).to be_empty Sentry::Rails::Tracing.remove_active_support_notifications_patch end From 7348bc6f9ed5a029b8b90a45926b8166c767ae94 Mon Sep 17 00:00:00 2001 From: st0012 Date: Sat, 18 Sep 2021 12:22:00 +0800 Subject: [PATCH 4/4] Update changelog --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8a9e8941a..e0a56ca95 100644 --- a/CHANGELOG.md +++ b/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