Fix error in EventHandler on request with error (#1114)

When a request has an error, it would give the `on_finish` callback a response object that is `nil`. This would break when we called `response.status`, and it would fail to complete the transaction. Make sure the transaction is always completed when it's handling a transaction, by putting the outside the safety block which fetches all the request and response metadata. Check if the `response` object is `nil` before calling other methods on it to the response status tag and metric. This way we don't raise an error. Luckily no integrations of ours that have been published yet would run into this behavior. The Rails integrations uses the EventHandler, but has its own error reporting. This would only be a problem for people who use the EventHandler directly, or when we move more integrations over to use AbstractMiddleware subclasses.
appsignal · Jun 26, 2024 · 0e48f19 · 0e48f19
1 parent 519b4f4
commit 0e48f19
Show file tree

Hide file tree

Showing 3 changed files with 117 additions and 30 deletions.
diff --git a/.changesets/fix-error-reporting-for-requests-with-an-error.md b/.changesets/fix-error-reporting-for-requests-with-an-error.md
@@ -0,0 +1,6 @@
+---
+bump: patch
+type: fix
+---
+
+Fix error reporting for requests with an error that use the AppSignal EventHandler.
diff --git a/lib/appsignal/rack/event_handler.rb b/lib/appsignal/rack/event_handler.rb
@@ -42,22 +42,22 @@ def on_start(request, _response)
 
           request.env[RACK_AFTER_REPLY] ||= []
           request.env[RACK_AFTER_REPLY] << proc do
+            next unless event_handler.request_handler?(request.env[APPSIGNAL_EVENT_HANDLER_ID])
+
             Appsignal::Rack::EventHandler
               .safe_execution("Appsignal::Rack::EventHandler's after_reply") do
-              next unless event_handler.request_handler?(request.env[APPSIGNAL_EVENT_HANDLER_ID])
-
               transaction.finish_event("process_request.rack", "", "")
               transaction.set_http_or_background_queue_start
-
-              # Make sure the current transaction is always closed when the request
-              # is finished. This is a fallback for in case the `on_finish`
-              # callback is not called. This is supported by servers like Puma and
-              # Unicorn.
-              #
-              # The EventHandler.on_finish callback should be called first, this is
-              # just a fallback if that doesn't get called.
-              Appsignal::Transaction.complete_current!
             end
+
+            # Make sure the current transaction is always closed when the request
+            # is finished. This is a fallback for in case the `on_finish`
+            # callback is not called. This is supported by servers like Puma and
+            # Unicorn.
+            #
+            # The EventHandler.on_finish callback should be called first, this is
+            # just a fallback if that doesn't get called.
+            Appsignal::Transaction.complete_current!
           end
           transaction.start_event
         end
@@ -75,26 +75,28 @@ def on_error(request, _response, error)
       end
 
       def on_finish(request, response)
-        self.class.safe_execution("Appsignal::Rack::EventHandler#on_finish") do
-          return unless request_handler?(request.env[APPSIGNAL_EVENT_HANDLER_ID])
+        return unless request_handler?(request.env[APPSIGNAL_EVENT_HANDLER_ID])
 
-          transaction = request.env[APPSIGNAL_TRANSACTION]
-          return unless transaction
+        transaction = request.env[APPSIGNAL_TRANSACTION]
+        return unless transaction
 
+        self.class.safe_execution("Appsignal::Rack::EventHandler#on_finish") do
           transaction.finish_event("process_request.rack", "", "")
-          transaction.set_tags(:response_status => response.status)
           transaction.set_http_or_background_queue_start
-          Appsignal.increment_counter(
-            :response_status,
-            1,
-            :status => response.status,
-            :namespace => format_namespace(transaction.namespace)
-          )
-
-          # Make sure the current transaction is always closed when the request
-          # is finished
-          Appsignal::Transaction.complete_current!
+          if response
+            transaction.set_tags(:response_status => response.status)
+            Appsignal.increment_counter(
+              :response_status,
+              1,
+              :status => response.status,
+              :namespace => format_namespace(transaction.namespace)
+            )
+          end
         end
+
+        # Make sure the current transaction is always closed when the request
+        # is finished
+        Appsignal::Transaction.complete_current!
       end
 
       private

diff --git a/spec/lib/appsignal/rack/event_handler_spec.rb b/spec/lib/appsignal/rack/event_handler_spec.rb
@@ -66,6 +66,30 @@ def on_start
       expect(last_transaction.ext.queue_start).to eq(queue_start_time)
     end
 
+    context "with error inside rack.after_reply handler" do
+      before do
+        on_start
+        # A random spot we can access to raise an error for this test
+        expect(request.env[Appsignal::Rack::APPSIGNAL_TRANSACTION])
+          .to receive(:finish_event)
+          .and_raise(ExampleStandardError, "oh no")
+        callback = request.env[Appsignal::Rack::RACK_AFTER_REPLY].first
+        callback.call
+      end
+
+      it "completes the transaction" do
+        expect(last_transaction).to be_completed
+      end
+
+      it "logs an error" do
+        expect(log).to contains_log(
+          :error,
+          "Error occurred in Appsignal::Rack::EventHandler's after_reply: " \
+            "ExampleStandardError: oh no"
+        )
+      end
+    end
+
     it "logs errors from rack.after_reply callbacks" do
       on_start
 
@@ -139,8 +163,8 @@ def on_error(error)
   describe "#on_finish" do
     let(:response) { Rack::Events::BufferedResponse.new(200, {}, ["body"]) }
 
-    def on_finish
-      event_handler_instance.on_finish(request, response)
+    def on_finish(given_request = request, given_response = response)
+      event_handler_instance.on_finish(given_request, given_response)
     end
 
     it "doesn't do anything without a transaction" do
@@ -155,6 +179,7 @@ def on_finish
         "sample_data" => {},
         "events" => []
       )
+      expect(last_transaction).to_not be_completed
     end
 
     it "completes the transaction" do
@@ -176,6 +201,60 @@ def on_finish
       expect(last_transaction).to be_completed
     end
 
+    context "without a response" do
+      it "completes the transaction" do
+        on_start
+        on_finish(request, nil)
+
+        expect(last_transaction.to_h).to include(
+          # The action is not set on purpose, as we can't set a normalized route
+          # It requires the app to set an action name
+          "action" => nil,
+          "sample_data" => hash_including(
+            "environment" => {
+              "REQUEST_METHOD" => "GET",
+              "PATH_INFO" => "/path"
+            }
+          )
+        )
+        expect(last_transaction.ext.queue_start).to eq(queue_start_time)
+        expect(last_transaction).to be_completed
+      end
+
+      it "does not set a response_status tag" do
+        on_start
+        on_finish(request, nil)
+
+        expect(last_transaction.to_h.dig("sample_data", "tags")).to_not have_key("response_status")
+      end
+
+      it "does not report a response_status counter metric" do
+        expect(Appsignal).to_not receive(:increment_counter)
+          .with(:response_status, anything, anything)
+
+        on_start
+        on_finish(request, nil)
+      end
+    end
+
+    context "with error inside on_finish handler" do
+      before do
+        on_start
+        # A random spot we can access to raise an error for this test
+        expect(Appsignal).to receive(:increment_counter).and_raise(ExampleStandardError, "oh no")
+        on_finish
+      end
+
+      it "completes the transaction" do
+        expect(last_transaction).to be_completed
+      end
+
+      it "logs an error" do
+        expect(log).to contains_log(:error,
+          "Error occurred in Appsignal::Rack::EventHandler#on_finish: ExampleStandardError: oh no")
+      end
+    end
+
     context "when the handler is nested in another EventHandler" do
       it "does not complete the transaction" do
         on_start
@@ -237,8 +316,8 @@ def on_finish
     end
 
     it "logs an error in case of an error" do
-      expect(Appsignal::Transaction)
-        .to receive(:complete_current!).and_raise(ExampleStandardError, "oh no")
+      # A random spot we can access to raise an error for this test
+      expect(Appsignal).to receive(:increment_counter).and_raise(ExampleStandardError, "oh no")
 
       on_start
       on_finish