From 39e33421044b7fbf22a2ab74fb92d5503c2a9c0a Mon Sep 17 00:00:00 2001
From: Tom de Bruijn <tom@tomdebruijn.com>
Date: Tue, 18 Jun 2024 12:24:14 +0200
Subject: [PATCH] Improve nested Sinatra app instrumentation

Sinatra apps, mounted in Rails app, would run into the issue that the
Rails middleware has already created a transaction for the request. It
would "force" a new transaction to be made, which loses information from
everything that happened before it.

Previously, before PR #1089, it would also leave a transaction that was
not closed properly. Even with that change, for one request, now two
transactions are created, one for Rails and one for the nested Sinatra
app.

This change reads if there's a current transaction from the request env,
and uses that instead of creating a new one. Some logic in the
Transaction class would read from the request object given to it on
`Transaction.create` to set metadata like parameters, so these need to
be set manually now.

It will also make sure not to close the transaction if one existed
already before this middleware was called.

Part of #329, the Rack middleware refactor.
---
 ...atra-apps-in-rails-apps-instrumentation.md |   6 +
 lib/appsignal/rack/sinatra_instrumentation.rb |  39 ++-
 .../rack/sinatra_instrumentation_spec.rb      | 302 ++++++++++--------
 3 files changed, 198 insertions(+), 149 deletions(-)
 create mode 100644 .changesets/improve-mounted-sinatra-apps-in-rails-apps-instrumentation.md

diff --git a/.changesets/improve-mounted-sinatra-apps-in-rails-apps-instrumentation.md b/.changesets/improve-mounted-sinatra-apps-in-rails-apps-instrumentation.md
new file mode 100644
index 000000000..2676b871d
--- /dev/null
+++ b/.changesets/improve-mounted-sinatra-apps-in-rails-apps-instrumentation.md
@@ -0,0 +1,6 @@
+---
+bump: patch
+type: change
+---
+
+Improve instrumentation for mounted Sinatra apps in Rails apps. The sample reported for the Sinatra request will now include the time spent in Rails and its middleware.
diff --git a/lib/appsignal/rack/sinatra_instrumentation.rb b/lib/appsignal/rack/sinatra_instrumentation.rb
index ef88c0f7d..877969c7e 100644
--- a/lib/appsignal/rack/sinatra_instrumentation.rb
+++ b/lib/appsignal/rack/sinatra_instrumentation.rb
@@ -46,17 +46,26 @@ def call(env)
         end
       end
 
+      private
+
       def call_with_appsignal_monitoring(env)
-        options = { :force => @options.include?(:force) && @options[:force] }
-        options.merge!(:params_method => @options[:params_method]) if @options[:params_method]
         request = @options.fetch(:request_class, Sinatra::Request).new(env)
-        transaction = Appsignal::Transaction.create(
-          SecureRandom.uuid,
-          Appsignal::Transaction::HTTP_REQUEST,
-          request,
-          options
-        )
+        has_parent_instrumentation = env.key?(Appsignal::Rack::APPSIGNAL_TRANSACTION)
+        transaction =
+          if has_parent_instrumentation
+            env[Appsignal::Rack::APPSIGNAL_TRANSACTION]
+          else
+            Appsignal::Transaction.create(
+              SecureRandom.uuid,
+              Appsignal::Transaction::HTTP_REQUEST,
+              request
+            )
+          end
+
         begin
+          params = fetch_params(request, @options.fetch(:params_method, :params))
+          transaction.params = params if params
+
           Appsignal.instrument("process_action.sinatra") do
             @app.call(env)
           end
@@ -73,7 +82,9 @@ def call_with_appsignal_monitoring(env)
           transaction.set_metadata("path", request.path)
           transaction.set_metadata("method", request.request_method)
           transaction.set_http_or_background_queue_start
-          Appsignal::Transaction.complete_current!
+
+          # Only close if this middleware created the instrumentation
+          Appsignal::Transaction.complete_current! unless has_parent_instrumentation
         end
       end
 
@@ -88,7 +99,15 @@ def action_name(env)
         end
       end
 
-      private
+      def fetch_params(request, params_method)
+        return unless request.respond_to?(params_method)
+
+        request.send(params_method)
+      rescue => error
+        # Getting params from the request has been know to fail.
+        Appsignal.internal_logger.debug "Exception while getting Sinatra params: #{error}"
+        nil
+      end
 
       def raise_errors?(app)
         app.respond_to?(:settings) &&
diff --git a/spec/lib/appsignal/rack/sinatra_instrumentation_spec.rb b/spec/lib/appsignal/rack/sinatra_instrumentation_spec.rb
index 279b45a9b..b7d7495e1 100644
--- a/spec/lib/appsignal/rack/sinatra_instrumentation_spec.rb
+++ b/spec/lib/appsignal/rack/sinatra_instrumentation_spec.rb
@@ -28,8 +28,7 @@ def make_request_with_error(env, error)
       before { allow(middleware).to receive(:raw_payload).and_return({}) }
 
       it "doesn't instrument requests" do
-        make_request(env)
-        expect(created_transactions.count).to eq(0)
+        expect { make_request(env) }.to_not(change { created_transactions.count })
       end
     end
 
@@ -47,7 +46,7 @@ def make_request_with_error(env, error)
 
     let(:settings) { double(:raise_errors => false) }
     let(:app) { double(:call => true, :settings => settings) }
-    let(:env) { { "sinatra.route" => "GET /", :path => "/", :method => "GET" } }
+    let(:env) { { "sinatra.route" => "GET /path", :path => "/path", :method => "GET" } }
     let(:options) { {} }
     let(:middleware) { Appsignal::Rack::SinatraBaseInstrumentation.new(app, options) }
 
@@ -93,216 +92,241 @@ def make_request_with_error(env, error)
     describe "#call" do
       before { allow(middleware).to receive(:raw_payload).and_return({}) }
 
-      context "when appsignal is active" do
-        it "instruments requests" do
-          expect(middleware).to receive(:call_with_appsignal_monitoring).with(env)
-        end
-      end
-
       context "when appsignal is not active" do
         before { allow(Appsignal).to receive(:active?).and_return(false) }
 
         it "does not instrument requests" do
-          expect(created_transactions.count).to eq(0)
+          expect { make_request(env) }.to_not(change { created_transactions.count })
         end
 
         it "calls the next middleware in the stack" do
           expect(app).to receive(:call).with(env)
+          make_request(env)
         end
       end
 
-      after { make_request(env) }
-    end
-
-    describe "#call_with_appsignal_monitoring" do
-      context "without an error" do
-        it "creates a transaction" do
+      context "when appsignal is active" do
+        it "calls the next middleware in the stack" do
           expect(app).to receive(:call).with(env)
-
           make_request(env)
-
-          expect(created_transactions.count).to eq(1)
-          expect(last_transaction.to_h).to include(
-            "namespace" => Appsignal::Transaction::HTTP_REQUEST,
-            "action" => "GET /",
-            "error" => nil,
-            "metadata" => { "path" => "" }
-          )
         end
-      end
 
-      context "with an error" do
-        let(:error) { ExampleException }
-        let(:app) do
-          double.tap do |d|
-            allow(d).to receive(:call).and_raise(error)
-            allow(d).to receive(:settings).and_return(settings)
+        context "without an error" do
+          before do
+            expect { make_request(env) }.to(change { created_transactions.count }.by(1))
           end
-        end
 
-        it "records the exception" do
-          make_request_with_error(env, error)
-
-          expect(created_transactions.count).to eq(1)
-          expect(last_transaction.to_h).to include(
-            "namespace" => Appsignal::Transaction::HTTP_REQUEST,
-            "action" => "GET /",
-            "error" => hash_including(
-              "name" => "ExampleException",
-              "message" => "ExampleException"
+          it "creates a transaction without an error" do
+            expect(last_transaction.to_h).to include(
+              "namespace" => Appsignal::Transaction::HTTP_REQUEST,
+              "action" => "GET /path",
+              "error" => nil,
+              "metadata" => { "path" => "" }
             )
-          )
-        end
-      end
-
-      context "with an error in sinatra.error" do
-        let(:error) { ExampleException.new }
-        let(:env) { { "sinatra.error" => error } }
+          end
 
-        context "when raise_errors is off" do
-          let(:settings) { double(:raise_errors => false) }
+          it "completes the transaction" do
+            expect(last_transaction).to be_completed
+          end
+        end
 
-          it "record the error" do
-            make_request(env)
+        context "with an error" do
+          let(:error) { ExampleException.new("error message") }
+          before do
+            allow(app).to receive(:call).and_raise(error)
+            expect { make_request_with_error(env, error) }
+              .to(change { created_transactions.count }.by(1))
+          end
 
-            expect(created_transactions.count).to eq(1)
+          it "creates and completes a transaction and records the exception" do
             expect(last_transaction.to_h).to include(
+              "namespace" => Appsignal::Transaction::HTTP_REQUEST,
+              "action" => "GET /path",
               "error" => hash_including(
                 "name" => "ExampleException",
-                "message" => "ExampleException"
+                "message" => "error message"
               )
             )
           end
-        end
-
-        context "when raise_errors is on" do
-          let(:settings) { double(:raise_errors => true) }
-
-          it "does not record the error" do
-            make_request(env)
 
-            expect(created_transactions.count).to eq(1)
-            expect(last_transaction.to_h).to include("error" => nil)
+          it "completes the transaction" do
+            expect(last_transaction).to be_completed
           end
         end
 
-        context "if sinatra.skip_appsignal_error is set" do
-          let(:env) { { "sinatra.error" => error, "sinatra.skip_appsignal_error" => true } }
+        context "with an error in sinatra.error" do
+          let(:error) { ExampleException.new("error message") }
+          let(:env) { { "sinatra.error" => error } }
 
-          it "does not record the error" do
-            make_request(env)
+          context "when raise_errors is off" do
+            let(:settings) { double(:raise_errors => false) }
+
+            it "record the error" do
+              expect { make_request(env) }
+                .to(change { created_transactions.count }.by(1))
 
-            expect(created_transactions.count).to eq(1)
-            expect(last_transaction.to_h).to include("error" => nil)
+              expect(last_transaction.to_h).to include(
+                "error" => hash_including(
+                  "name" => "ExampleException",
+                  "message" => "error message"
+                )
+              )
+            end
           end
-        end
-      end
 
-      describe "action name" do
-        it "sets the action" do
-          make_request(env)
+          context "when raise_errors is on" do
+            let(:settings) { double(:raise_errors => true) }
 
-          expect(created_transactions.count).to eq(1)
-          expect(last_transaction.to_h).to include("action" => "GET /")
-        end
+            it "does not record the error" do
+              expect { make_request(env) }
+                .to(change { created_transactions.count }.by(1))
 
-        context "without 'sinatra.route' env" do
-          let(:env) { { :path => "/", :method => "GET" } }
+              expect(last_transaction.to_h).to include("error" => nil)
+            end
+          end
 
-          it "doesn't set an action name" do
-            make_request(env)
+          context "if sinatra.skip_appsignal_error is set" do
+            let(:env) { { "sinatra.error" => error, "sinatra.skip_appsignal_error" => true } }
 
-            expect(created_transactions.count).to eq(1)
-            expect(last_transaction.to_h).to include("action" => nil)
+            it "does not record the error" do
+              expect { make_request(env) }
+                .to(change { created_transactions.count }.by(1))
+
+              expect(last_transaction.to_h).to include("error" => nil)
+            end
           end
         end
 
-        context "with mounted modular application" do
-          before { env["SCRIPT_NAME"] = "/api" }
-
-          it "should call set_action with an application prefix path" do
+        describe "action name" do
+          it "sets the action to the request method and path" do
             make_request(env)
 
-            expect(created_transactions.count).to eq(1)
-            expect(last_transaction.to_h).to include("action" => "GET /api/")
+            expect(last_transaction.to_h).to include("action" => "GET /path")
           end
 
           context "without 'sinatra.route' env" do
-            let(:env) { { :path => "/", :method => "GET" } }
+            let(:env) { { :path => "/path", :method => "GET" } }
 
             it "doesn't set an action name" do
               make_request(env)
 
-              expect(created_transactions.count).to eq(1)
               expect(last_transaction.to_h).to include("action" => nil)
             end
           end
+
+          context "with mounted modular application" do
+            before { env["SCRIPT_NAME"] = "/api" }
+
+            it "sets the action name with an application prefix path" do
+              make_request(env)
+
+              expect(last_transaction.to_h).to include("action" => "GET /api/path")
+            end
+
+            context "without 'sinatra.route' env" do
+              let(:env) { { :path => "/path", :method => "GET" } }
+
+              it "doesn't set an action name" do
+                make_request(env)
+
+                expect(last_transaction.to_h).to include("action" => nil)
+              end
+            end
+          end
         end
-      end
 
-      context "metadata" do
-        let(:env) { { "PATH_INFO" => "/some/path", "REQUEST_METHOD" => "GET" } }
+        context "metadata" do
+          let(:env) { { "PATH_INFO" => "/some/path", "REQUEST_METHOD" => "GET" } }
 
-        it "sets metadata from the environment" do
-          make_request(env)
+          it "sets metadata from the environment" do
+            make_request(env)
 
-          expect(created_transactions.count).to eq(1)
-          expect(last_transaction.to_h).to include(
-            "metadata" => {
-              "method" => "GET",
-              "path" => "/some/path"
-            },
-            "sample_data" => hash_including(
-              "environment" => hash_including(
-                "REQUEST_METHOD" => "GET",
-                "PATH_INFO" => "/some/path"
+            expect(last_transaction.to_h).to include(
+              "metadata" => {
+                "method" => "GET",
+                "path" => "/some/path"
+              },
+              "sample_data" => hash_including(
+                "environment" => hash_including(
+                  "REQUEST_METHOD" => "GET",
+                  "PATH_INFO" => "/some/path"
+                )
               )
             )
-          )
+          end
         end
-      end
 
-      context "with queue start" do
-        let(:queue_start_time) { fixed_time * 1_000 }
-        let(:env) do
-          { "HTTP_X_REQUEST_START" => "t=#{queue_start_time.to_i}" } # in milliseconds
-        end
+        context "with queue start" do
+          let(:queue_start_time) { fixed_time * 1_000 }
+          let(:env) do
+            { "HTTP_X_REQUEST_START" => "t=#{queue_start_time.to_i}" } # in milliseconds
+          end
 
-        it "sets the queue start" do
-          make_request(env)
-          expect(last_transaction.ext.queue_start).to eq(queue_start_time)
+          it "sets the queue start" do
+            make_request(env)
+            expect(last_transaction.ext.queue_start).to eq(queue_start_time)
+          end
         end
-      end
 
-      class FilteredRequest
-        def initialize(_args) # rubocop:disable Style/RedundantInitialize
-        end
+        class FilteredRequest
+          def initialize(_args) # rubocop:disable Style/RedundantInitialize
+          end
 
-        def path
-          "/static/path"
-        end
+          def path
+            "/static/path"
+          end
+
+          def request_method
+            "GET"
+          end
 
-        def request_method
-          "GET"
+          def filtered_params
+            { "abc" => "123" }
+          end
         end
 
-        def filtered_params
-          { "abc" => "123" }
+        context "with overridden request class and params method" do
+          let(:options) do
+            { :request_class => FilteredRequest, :params_method => :filtered_params }
+          end
+
+          it "uses the overridden request class and params method to fetch params" do
+            make_request(env)
+
+            expect(last_transaction.to_h).to include(
+              "sample_data" => hash_including(
+                "params" => { "abc" => "123" }
+              )
+            )
+          end
         end
-      end
 
-      context "with overridden request class and params method" do
-        let(:options) { { :request_class => FilteredRequest, :params_method => :filtered_params } }
+        context "with parent instrumentation" do
+          before do
+            env["PATH_INFO"] = "/some/path"
+            env["REQUEST_METHOD"] = "GET"
+            env[Appsignal::Rack::APPSIGNAL_TRANSACTION] = http_request_transaction
+            make_request(env)
+          end
 
-        it "uses the overridden request class and params method to fetch params" do
-          make_request(env)
+          it "uses the existing transaction" do
+            expect { make_request(env) }.to_not(change { created_transactions.count })
+          end
 
-          expect(created_transactions.count).to eq(1)
-          expect(last_transaction.to_h).to include(
-            "sample_data" => hash_including(
-              "params" => { "abc" => "123" }
+          it "sets metadata on the transaction" do
+            expect(env[Appsignal::Rack::APPSIGNAL_TRANSACTION].to_h).to include(
+              "namespace" => Appsignal::Transaction::HTTP_REQUEST,
+              "action" => "GET /path",
+              "metadata" => {
+                "method" => "GET",
+                "path" => "/some/path"
+              }
             )
-          )
+          end
+
+          it "doesn't complete the existing transaction" do
+            expect(env[Appsignal::Rack::APPSIGNAL_TRANSACTION]).to_not be_completed
+          end
         end
       end
     end