Guard blocks handed to the transaction

A transaction runs blocks supplied by user code in a few places: the
error block passed to `set_error`, `send_error`, and `report_error`, and
the `after_create` and `before_complete` hooks. Any of them can raise.

These blocks can run far from where they were defined. In agent mode an
error block runs at completion, not when the error is added. So a raise
propagated out of whatever drove creation or completion, surfacing the
error in unrelated code. In collector mode it also skipped the backend's
completion step, which left the transaction's OpenTelemetry context
attached to the fiber. That leaked context then became the parent of the
next request's root span on the reused thread, merging unrelated
requests into one trace. Agent mode never showed the leak because its
extension handle is not a per-fiber stack.

Run each of these blocks defensively. On failure, log the error and the
block's definition site, then carry on so creation and completion always
finish. The error is swallowed rather than re-raised, because the block
can run far from its caller and re-raising would surface it in code that
has nothing to do with the block.

Author: unflxw

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

@@ -0,0 +1,6 @@
+---
+bump: patch
+type: fix
+---
+
+Complete the transaction even when a block handed to it raises. The error block passed to `Appsignal.set_error`, `Appsignal.send_error`, and `Appsignal.report_error`, as well as the internal `after_create` and `before_complete` hooks, are user code that can raise. Until now such an exception propagated out of transaction creation or completion, which surfaced the error in unrelated code and 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/transaction.rb

@@ -751,7 +751,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
+            call_transaction_block(block, self, :source => "error")
+          end
+        end
       else
         @error_blocks[error] << block
         @error_blocks[error].compact!
@@ -760,15 +764,34 @@ def internal_set_error(error, &block)
 
     private
 
+    # Run a block handed to the transaction by user code -- an error block from
+    # `set_error`/`send_error`/`report_error`, or an `after_create`/
+    # `before_complete` hook -- without letting it break the transaction
+    # lifecycle. These blocks can run far from where they were defined (an error
+    # block runs at completion in agent mode), so a failure is logged and
+    # swallowed rather than raised into whatever drove creation or completion.
+    # Re-raising would surface the error in unrelated code and, in collector
+    # mode, leave the OpenTelemetry context attached to the fiber -- leaking it
+    # into the next request on that thread.
+    def call_transaction_block(block, *args, source:)
+      block.call(*args)
+    rescue => e
+      location = block.source_location&.join(":") || "unknown location"
+      Appsignal.internal_logger.error(
+        "Error in #{source} block defined at #{location}: " \
+          "#{e.class}: #{e.message}\n#{e.backtrace&.join("\n")}"
+      )
+    end
+
     def run_after_create_hooks
       self.class.after_create.each do |block|
-        block.call(self)
+        call_transaction_block(block, self, :source => "after_create hook")
       end
     end
 
     def run_before_complete_hooks
       self.class.before_complete.each do |block|
-        block.call(self, @error_set)
+        call_transaction_block(block, self, @error_set, :source => "before_complete hook")
       end
     end
 
@@ -799,7 +822,9 @@ def report_errors_as_duplicates
           # with a block that calls all the blocks set for that error
           # in the original transaction.
           transaction.internal_set_error(error) do
-            @error_blocks[error].each { |block| block.call(transaction) }
+            @error_blocks[error].each do |block|
+              call_transaction_block(block, transaction, :source => "error")
+            end
           end
 
           transaction.complete
@@ -810,7 +835,7 @@ def report_errors_as_duplicates
 
       self.class.with_transaction(self) do
         @error_blocks[@error_set].each do |block|
-          block.call(self)
+          call_transaction_block(block, self, :source => "error")
         end
       end
     end

spec/lib/appsignal/transaction_spec.rb

@@ -226,6 +226,108 @@
     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 error block 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 before_complete hook block 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 after_create hook block 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 }