Fix sentry-rails' controller span nesting (#1973)

* Wrap controller actions inside a Sentry.with_child_span call

This makes sure all spans generated inside the controller call will be attached
under the controller span instead of the request span.

* Stop using ActionControllerSubscriber

Now we wrap controller action inside `Sentry.with_child_span`, we don't need
to register the `ActionControllerSubscriber` anymore.

However, we still can't remove it because users may reference the constant
directly when customizing the tracing subscribers config.

* Deprecate the ActionControllerSubscriber

* Update changelog

CHANGELOG.md

@@ -26,6 +26,8 @@
   - Fixes [#1956](https://github.com/getsentry/sentry-ruby/issues/1956)
 - Return value from `perform_action` in ActionCable::Channel instances when initialized [#1966](https://github.com/getsentry/sentry-ruby/pull/1966)
 - `Span#with_child_span` should finish the span even with exception raised [#1982](https://github.com/getsentry/sentry-ruby/pull/1982)
+- Fix sentry-rails' controller span nesting [#1973](https://github.com/getsentry/sentry-ruby/pull/1973)
+  - Fixes [#1899](https://github.com/getsentry/sentry-ruby/issues/1899)
 
 ## 5.7.0
 

sentry-rails/lib/sentry/rails/configuration.rb

@@ -83,7 +83,6 @@ def initialize
           %r(\A/{0,2}#{::Rails.application.config.assets.prefix})
         end
         @tracing_subscribers = Set.new([
-          Sentry::Rails::Tracing::ActionControllerSubscriber,
           Sentry::Rails::Tracing::ActionViewSubscriber,
           Sentry::Rails::Tracing::ActiveRecordSubscriber,
           Sentry::Rails::Tracing::ActiveStorageSubscriber

sentry-rails/lib/sentry/rails/controller_transaction.rb

@@ -2,10 +2,34 @@ module Sentry
   module Rails
     module ControllerTransaction
       def self.included(base)
-        base.prepend_before_action do |controller|
-          if Sentry.initialized?
-            Sentry.get_current_scope.set_transaction_name("#{controller.class}##{controller.action_name}", source: :view)
+        base.prepend_around_action(:sentry_around_action)
+      end
+
+      private
+
+      def sentry_around_action
+        if Sentry.initialized?
+          transaction_name = "#{self.class}##{action_name}"
+          Sentry.get_current_scope.set_transaction_name(transaction_name, source: :view)
+          Sentry.with_child_span(op: "view.process_action.action_controller", description: transaction_name) do |child_span|
+            if child_span
+              begin
+                result = yield
+              ensure
+                child_span.set_http_status(response.status)
+                child_span.set_data(:format, request.format)
+                child_span.set_data(:method, request.method)
+                child_span.set_data(:path, request.path)
+                child_span.set_data(:params, request.params)
+              end
+
+              result
+            else
+              yield
+            end
           end
+        else
+          yield
         end
       end
     end

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

@@ -11,6 +11,11 @@ class ActionControllerSubscriber < AbstractSubscriber
         OP_NAME = "view.process_action.action_controller".freeze
 
         def self.subscribe!
+          Sentry.logger.warn <<~MSG
+            DEPRECATION WARNING: sentry-rails has changed its approach on controller span recording and #{self.name} is now depreacted.
+            Please stop using or referencing #{self.name} as it will be removed in the next major release.
+          MSG
+
           subscribe_to_event(EVENT_NAMES) do |event_name, duration, payload|
             controller = payload[:controller]
             action = payload[:action]

sentry-rails/spec/sentry/rails/configuration_spec.rb

@@ -23,12 +23,12 @@
     class MySubscriber; end
 
     it "returns the default subscribers" do
-      expect(subject.tracing_subscribers.size).to eq(4)
+      expect(subject.tracing_subscribers.size).to eq(3)
     end
 
     it "is customizable" do
       subject.tracing_subscribers << MySubscriber
-      expect(subject.tracing_subscribers.size).to eq(5)
+      expect(subject.tracing_subscribers.size).to eq(4)
     end
 
     it "is replaceable" do

sentry-rails/spec/sentry/rails/tracing/action_controller_subscriber_spec.rb

@@ -6,28 +6,39 @@
   end
 
   context "when transaction is sampled" do
+    let(:string_io) { StringIO.new }
+    let(:logger) do
+      ::Logger.new(string_io)
+    end
+
     before do
       make_basic_app do |config|
         config.traces_sample_rate = 1.0
         config.rails.tracing_subscribers = [described_class]
+        config.logger = logger
       end
     end
 
+    it "logs deprecation message" do
+      expect(string_io.string).to include(
+        "DEPRECATION WARNING: sentry-rails has changed its approach on controller span recording and Sentry::Rails::Tracing::ActionControllerSubscriber is now depreacted."
+      )
+    end
+
     it "records controller action processing event" do
       get "/world"
 
       expect(transport.events.count).to eq(1)
 
       transaction = transport.events.first.to_hash
       expect(transaction[:type]).to eq("transaction")
-      expect(transaction[:spans].count).to eq(1)
+      expect(transaction[:spans].count).to eq(2)
 
       span = transaction[:spans][0]
       expect(span[:op]).to eq("view.process_action.action_controller")
       expect(span[:description]).to eq("HelloController#world")
       expect(span[:trace_id]).to eq(transaction.dig(:contexts, :trace, :trace_id))
-      expect(span[:data][:payload].keys).not_to include(:request)
-      expect(span[:data][:payload].keys).not_to include(:headers)
+      expect(span[:data].keys).to match_array(["status_code", :format, :method, :path, :params])
     end
   end
 

sentry-rails/spec/sentry/rails/tracing/action_view_subscriber_spec.rb

@@ -20,9 +20,10 @@
 
       transaction = transport.events.first.to_hash
       expect(transaction[:type]).to eq("transaction")
-      expect(transaction[:spans].count).to eq(1)
+      expect(transaction[:spans].count).to eq(2)
 
-      span = transaction[:spans][0]
+      # ignore the first span, which is for controller action
+      span = transaction[:spans][1]
       expect(span[:op]).to eq("template.render_template.action_view")
       expect(span[:description]).to match(/test_template\.html\.erb/)
       expect(span[:trace_id]).to eq(transaction.dig(:contexts, :trace, :trace_id))

sentry-rails/spec/sentry/rails/tracing/active_storage_subscriber_spec.rb

@@ -37,9 +37,9 @@
 
       request_transaction = transport.events.last.to_hash
       expect(request_transaction[:type]).to eq("transaction")
-      expect(request_transaction[:spans].count).to eq(1)
+      expect(request_transaction[:spans].count).to eq(2)
 
-      span = request_transaction[:spans][0]
+      span = request_transaction[:spans][1]
       expect(span[:op]).to eq("file.service_upload.active_storage")
       expect(span[:description]).to eq("Disk")
       expect(span.dig(:data, :key)).to eq(p.cover.key)

sentry-rails/spec/sentry/rails/tracing_spec.rb

@@ -36,17 +36,19 @@
       expect(transaction[:spans].count).to eq(2)
 
       first_span = transaction[:spans][0]
-      expect(first_span[:op]).to eq("db.sql.active_record")
-      expect(first_span[:description]).to eq("SELECT \"posts\".* FROM \"posts\"")
+      expect(first_span[:op]).to eq("view.process_action.action_controller")
+      expect(first_span[:description]).to eq("PostsController#index")
       expect(first_span[:parent_span_id]).to eq(parent_span_id)
-
-      # this is to make sure we calculate the timestamp in the correct scale (second instead of millisecond)
-      expect(first_span[:timestamp] - first_span[:start_timestamp]).to be_between(10.0 / 1_000_000, 10.0 / 1000)
+      expect(first_span[:status]).to eq("internal_error")
+      expect(first_span[:data].keys).to match_array(["status_code", :format, :method, :path, :params])
 
       second_span = transaction[:spans][1]
-      expect(second_span[:op]).to eq("view.process_action.action_controller")
-      expect(second_span[:description]).to eq("PostsController#index")
-      expect(second_span[:parent_span_id]).to eq(parent_span_id)
+      expect(second_span[:op]).to eq("db.sql.active_record")
+      expect(second_span[:description]).to eq("SELECT \"posts\".* FROM \"posts\"")
+      expect(second_span[:parent_span_id]).to eq(first_span[:span_id])
+
+      # this is to make sure we calculate the timestamp in the correct scale (second instead of millisecond)
+      expect(second_span[:timestamp] - second_span[:start_timestamp]).to be_between(10.0 / 1_000_000, 10.0 / 1000)
     end
 
     it "records transaction alone" do
@@ -65,22 +67,27 @@
       expect(transaction[:spans].count).to eq(3)
 
       first_span = transaction[:spans][0]
-      expect(first_span[:op]).to eq("db.sql.active_record")
-      expect(first_span[:description].squeeze("\s")).to eq(
+      expect(first_span[:data].keys).to match_array(["status_code", :format, :method, :path, :params])
+      expect(first_span[:op]).to eq("view.process_action.action_controller")
+      expect(first_span[:description]).to eq("PostsController#show")
+      expect(first_span[:parent_span_id]).to eq(parent_span_id)
+      expect(first_span[:status]).to eq("ok")
+
+
+      second_span = transaction[:spans][1]
+      expect(second_span[:op]).to eq("db.sql.active_record")
+      expect(second_span[:description].squeeze("\s")).to eq(
         'SELECT "posts".* FROM "posts" WHERE "posts"."id" = ? LIMIT ?'
       )
-      expect(first_span[:parent_span_id]).to eq(parent_span_id)
+      expect(second_span[:parent_span_id]).to eq(first_span[:span_id])
 
       # this is to make sure we calculate the timestamp in the correct scale (second instead of millisecond)
-      expect(first_span[:timestamp] - first_span[:start_timestamp]).to be_between(10.0 / 1_000_000, 10.0 / 1000)
-
-      last_span = transaction[:spans][2]
-      expect(last_span[:data][:payload].keys).not_to include(:headers)
-      expect(last_span[:data][:payload].keys).not_to include(:request)
-      expect(last_span[:data][:payload].keys).not_to include(:response)
-      expect(last_span[:op]).to eq("view.process_action.action_controller")
-      expect(last_span[:description]).to eq("PostsController#show")
-      expect(last_span[:parent_span_id]).to eq(parent_span_id)
+      expect(second_span[:timestamp] - second_span[:start_timestamp]).to be_between(10.0 / 1_000_000, 10.0 / 1000)
+
+      third_span = transaction[:spans][2]
+      expect(third_span[:op]).to eq("template.render_template.action_view")
+      expect(third_span[:description].squeeze("\s")).to eq("text template")
+      expect(third_span[:parent_span_id]).to eq(first_span[:span_id])
     end
 
     it "doesn't mess with custom instrumentations" do
@@ -197,8 +204,8 @@
 
       expect(transaction[:type]).to eq("transaction")
       expect(transaction[:transaction]).to eq("PostsController#show")
-      second_span = transaction[:spans][2]
-      expect(second_span[:description]).to eq("PostsController#show")
+      first_span = transaction[:spans][0]
+      expect(first_span[:description]).to eq("PostsController#show")
     end
 
     context "with sentry-trace and baggage headers" do