diff --git a/.changesets/complete-transaction-when-a-block-raises.md b/.changesets/complete-transaction-when-a-block-raises.md new file mode 100644 index 000000000..05e294f91 --- /dev/null +++ b/.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. diff --git a/lib/appsignal/helpers/instrumentation.rb b/lib/appsignal/helpers/instrumentation.rb index cb7ef2f34..44bc681f0 100644 --- a/lib/appsignal/helpers/instrumentation.rb +++ b/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 diff --git a/lib/appsignal/transaction.rb b/lib/appsignal/transaction.rb index 348d015b6..d442d1ec1 100644 --- a/lib/appsignal/transaction.rb +++ b/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 diff --git a/spec/lib/appsignal/transaction_spec.rb b/spec/lib/appsignal/transaction_spec.rb index 3a8dd43f2..120123102 100644 --- a/spec/lib/appsignal/transaction_spec.rb +++ b/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 diff --git a/spec/lib/appsignal_spec.rb b/spec/lib/appsignal_spec.rb index b7b3924d7..625a79b24 100644 --- a/spec/lib/appsignal_spec.rb +++ b/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