Guard blocks handed to the transaction

.changesets/complete-transaction-when-a-block-raises.md

@@ -0,0 +1,10 @@
+---
+bump: patch
+type: fix
+---
+
+Complete the transaction even when a block handed to it raises.
+
+The error block given to `Appsignal.send_error` and `Appsignal.report_error`, and the internal `after_create` and `before_complete` hooks, are user code that can raise. An error block runs at completion in agent mode, and the hooks run during creation and completion, so these blocks run far from where they were defined.
+
+Until now, an exception from any of these blocks propagated out of transaction creation or completion. That surfaced the error in unrelated code, and it could leave the transaction unfinished. These blocks are now run defensively. The failure is logged, naming the error and where the block was defined, and creation and completion carry on.

lib/appsignal/helpers/instrumentation.rb

@@ -238,7 +238,7 @@ def send_error(error, &block)
 
         transaction =
           Appsignal::Transaction.new(Appsignal::Transaction::HTTP_REQUEST)
-        transaction.set_error(error, &block)
+        transaction.set_error(error, :source => "Appsignal.send_error", &block)
 
         transaction.complete
       end
@@ -373,7 +373,7 @@ def report_error(exception, &block)
             Appsignal::Transaction.new(Appsignal::Transaction::HTTP_REQUEST)
           end
 
-        transaction.add_error(exception, &block)
+        transaction.add_error(exception, :source => "Appsignal.report_error", &block)
 
         transaction.complete unless has_parent_transaction
       end

lib/appsignal/transaction.rb

@@ -627,7 +627,7 @@ def set_metadata(key, value)
 
     # @!visibility private
     # @see Appsignal::Helpers::Instrumentation#report_error
-    def add_error(error, &block)
+    def add_error(error, source: nil, &block)
       unless error.is_a?(Exception)
         Appsignal.internal_logger.error "Appsignal::Transaction#add_error: Cannot add error. " \
           "The given value is not an exception: #{error.inspect}"
@@ -641,6 +641,11 @@ def add_error(error, &block)
         return
       end
 
+      # Wrap the block here, at the entry point, so it stays protected wherever
+      # it later runs: right away in collector mode, or at completion in agent
+      # mode. `source` names the helper the block was given to, when known, so
+      # the log points the customer at the right call.
+      block = protect(source ? "the block passed to #{source}" : "the error block", &block) if block
       internal_set_error(error, &block)
 
       # Mark errors and their causes as tracked so we don't report duplicates,
@@ -751,7 +756,11 @@ def internal_set_error(error, &block)
         # span -- breadcrumbs, nested errors, custom instrumentation -- then
         # lands where the error was reported, not on the root span at
         # completion.
-        self.class.with_transaction(self) { block.call(self) } if block
+        if block
+          self.class.with_transaction(self) do
+            block.call(self)
+          end
+        end
       else
         @error_blocks[error] << block
         @error_blocks[error].compact!
@@ -760,15 +769,44 @@ def internal_set_error(error, &block)
 
     private
 
+    # Wrap a block handed to the transaction by user code so that, wherever it
+    # later runs, a failure is logged and swallowed instead of breaking the
+    # transaction lifecycle. An error block runs at completion in agent mode,
+    # and the `after_create`/`before_complete` hooks run during creation and
+    # completion, so a raise would otherwise skip the rest of that work. In
+    # collector mode that includes the backend teardown that detaches the
+    # transaction's OpenTelemetry context, which would then leak onto the fiber
+    # and become the parent of the next request's spans on that thread.
+    # Re-raising is wrong because the block runs far from where its caller
+    # defined it, so the error would surface in unrelated code.
+    #
+    # Returns `nil` when no block is given, so it can wrap an optional block.
+    def protect(description, &block)
+      return unless block
+
+      proc do |*args|
+        block.call(*args)
+      rescue => error
+        location = block.source_location&.join(":") || "an unknown location"
+        Appsignal.internal_logger.error(
+          "Error in #{description}, defined at #{location}: " \
+            "#{error.class}: #{error.message}\n#{error.backtrace&.join("\n")}"
+        )
+      end
+    end
+
+    # Hooks are registered both as blocks and as method objects pushed onto the
+    # set directly, so there is no single entry point to wrap them at. They are
+    # protected here instead, at the one place that runs all of them.
     def run_after_create_hooks
       self.class.after_create.each do |block|
-        block.call(self)
+        protect("the after_create hook", &block).call(self)
       end
     end
 
     def run_before_complete_hooks
       self.class.before_complete.each do |block|
-        block.call(self, @error_set)
+        protect("the before_complete hook", &block).call(self, @error_set)
       end
     end
 
@@ -797,9 +835,12 @@ def report_errors_as_duplicates
         duplicate.tap do |transaction|
           # In the duplicate transaction for each error, set an error
           # with a block that calls all the blocks set for that error
-          # in the original transaction.
+          # in the original transaction. Those blocks were already wrapped
+          # when they were added, so they are called directly here.
           transaction.internal_set_error(error) do
-            @error_blocks[error].each { |block| block.call(transaction) }
+            @error_blocks[error].each do |block|
+              block.call(transaction)
+            end
           end
 
           transaction.complete

spec/lib/appsignal/transaction_spec.rb

@@ -226,6 +226,126 @@
     end
   end
 
+  # A block handed to AppSignal (an error block, or an after_create/
+  # before_complete hook) is user code that can raise. Because these blocks
+  # can run far from where they were defined -- an error block runs at
+  # completion in agent mode -- a failure must be logged and swallowed, never
+  # raised into whatever drove creation or completion. Otherwise, in collector
+  # mode, the transaction's OpenTelemetry context is left attached to the
+  # fiber and leaks into the next request on that thread.
+  describe "when a block handed to the transaction raises" do
+    describe "an error block" do
+      it_in_both_modes "completes the transaction and logs, without raising" do
+        transaction = create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+
+        logs = capture_logs do
+          expect do
+            transaction.add_error(ExampleStandardError.new("boom")) do
+              raise ExampleStandardError, "error block boom"
+            end
+            Appsignal::Transaction.complete_current!
+          end.to_not raise_error
+        end
+
+        expect(transaction).to be_completed
+        expect(logs).to contains_log(:error,
+          /Error in the error block, defined at .+error block boom/)
+      end
+
+      it "names the reporting helper in the log when a source is given" do
+        transaction = create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+
+        logs = capture_logs do
+          transaction.add_error(
+            ExampleStandardError.new("boom"),
+            :source => "Appsignal.send_error"
+          ) { raise ExampleStandardError, "error block boom" }
+          Appsignal::Transaction.complete_current!
+        end
+
+        expect(logs).to contains_log(
+          :error,
+          /Error in the block passed to Appsignal\.send_error, defined at .+error block boom/
+        )
+      end
+
+      it "detaches the OpenTelemetry context", :collector_mode do
+        start_collector_agent
+        transaction = create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+
+        expect do
+          transaction.add_error(ExampleStandardError.new("boom")) do
+            raise ExampleStandardError, "error block boom"
+          end
+          Appsignal::Transaction.complete_current!
+        end.to_not raise_error
+
+        expect(::OpenTelemetry::Trace.current_span)
+          .to eq(::OpenTelemetry::Trace::Span::INVALID)
+      end
+    end
+
+    describe "a before_complete hook" do
+      it_in_both_modes "completes the transaction and logs, without raising" do
+        Appsignal::Transaction.before_complete do |_transaction, _error|
+          raise ExampleStandardError, "before_complete boom"
+        end
+        transaction = create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+
+        logs = capture_logs do
+          expect { Appsignal::Transaction.complete_current! }.to_not raise_error
+        end
+
+        expect(transaction).to be_completed
+        expect(logs).to contains_log(
+          :error, /Error in the before_complete hook, defined at .+before_complete boom/
+        )
+      end
+
+      it "detaches the OpenTelemetry context", :collector_mode do
+        start_collector_agent
+        Appsignal::Transaction.before_complete do |_transaction, _error|
+          raise ExampleStandardError, "before_complete boom"
+        end
+        create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+
+        expect { Appsignal::Transaction.complete_current! }.to_not raise_error
+        expect(::OpenTelemetry::Trace.current_span)
+          .to eq(::OpenTelemetry::Trace::Span::INVALID)
+      end
+    end
+
+    describe "an after_create hook" do
+      it_in_both_modes "creates the transaction and logs, without raising" do
+        Appsignal::Transaction.after_create do |_transaction|
+          raise ExampleStandardError, "after_create boom"
+        end
+
+        logs = capture_logs do
+          expect { create_transaction(Appsignal::Transaction::HTTP_REQUEST) }
+            .to_not raise_error
+        end
+
+        expect(logs).to contains_log(
+          :error, /Error in the after_create hook, defined at .+after_create boom/
+        )
+      end
+
+      it "detaches the OpenTelemetry context on the next completion", :collector_mode do
+        start_collector_agent
+        Appsignal::Transaction.after_create do |_transaction|
+          raise ExampleStandardError, "after_create boom"
+        end
+
+        create_transaction(Appsignal::Transaction::HTTP_REQUEST)
+        Appsignal::Transaction.complete_current!
+
+        expect(::OpenTelemetry::Trace.current_span)
+          .to eq(::OpenTelemetry::Trace::Span::INVALID)
+      end
+    end
+  end
+
   describe ".current" do
     context "when there is a current transaction" do
       let!(:transaction) { create_transaction }
@@ -3185,14 +3305,17 @@ def perform
     end
 
     context "when a block is given" do
-      it "stores the block in the error blocks" do
-        block = proc { "block" }
+      it "stores the block, wrapped, in the error blocks" do
+        called_with = nil
+        transaction.add_error(error) { |t| called_with = t }
 
-        transaction.add_error(error, &block)
+        stored = transaction.error_blocks[error]
+        expect(stored.size).to eq(1)
 
-        expect(transaction.error_blocks).to eq({
-          error => [block]
-        })
+        # The block is wrapped when it is added, so what is stored is not the
+        # given block itself but a wrapper that calls through to it.
+        stored.each { |block| block.call(transaction) }
+        expect(called_with).to eq(transaction)
       end
     end
 
@@ -3408,12 +3531,15 @@ def perform
       end
 
       context "when a block is given" do
-        it "adds the block to the error blocks" do
-          block = proc { "block" }
+        it "adds the block, wrapped, to the error blocks" do
+          called = false
+          transaction.add_error(error) { called = true }
 
-          transaction.add_error(error, &block)
+          stored = transaction.error_blocks[error]
+          expect(stored.size).to eq(1)
 
-          expect(transaction.error_blocks).to eq({ error => [block] })
+          stored.each { |block| block.call(transaction) }
+          expect(called).to be(true)
         end
       end
     end
@@ -3459,12 +3585,15 @@ def perform
           expect(transaction.error_blocks.length).to eq(10)
         end
 
-        it "does add the block to the error blocks" do
-          block = proc { "block" }
+        it "does add the block, wrapped, to the error blocks" do
+          called = false
+          transaction.add_error(seen_error) { called = true }
 
-          transaction.add_error(seen_error, &block)
+          stored = transaction.error_blocks[seen_error]
+          expect(stored.size).to eq(1)
 
-          expect(transaction.error_blocks[seen_error]).to eq([block])
+          stored.each { |block| block.call(transaction) }
+          expect(called).to be(true)
         end
 
         it "does not log a debug message" do

spec/lib/appsignal_spec.rb

@@ -2019,6 +2019,21 @@ def perform
           expect(last_transaction).to have_error("StandardError", "my_error")
         end
 
+        it "logs a raising block without raising, naming the helper" do
+          logs = capture_logs do
+            expect do
+              Appsignal.send_error(StandardError.new("my_error")) do
+                raise ExampleStandardError, "metadata boom"
+              end
+            end.to_not raise_error
+          end
+
+          expect(logs).to contains_log(
+            :error,
+            /Error in the block passed to Appsignal\.send_error, defined at .+metadata boom/
+          )
+        end
+
         it "yields to set metadata and doesn't modify the active transaction" do
           active_transaction = http_request_transaction
           active_transaction.set_action("active action")
@@ -2220,6 +2235,21 @@ def perform
             expect(transaction).to include_tags("tag1" => "value1")
             expect(transaction).to be_completed
           end
+
+          it "logs a raising block without raising, naming the helper" do
+            logs = capture_logs do
+              expect do
+                Appsignal.report_error(error) do
+                  raise ExampleStandardError, "metadata boom"
+                end
+              end.to_not raise_error
+            end
+
+            expect(logs).to contains_log(
+              :error,
+              /Error in the block passed to Appsignal\.report_error, defined at .+metadata boom/
+            )
+          end
         end
       end