From d0d93d11bbe71f686e8d23ca36de0086b5c95659 Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Thu, 20 Apr 2023 09:27:42 -0700 Subject: [PATCH 1/8] check if txn finished in thread instrumentation --- lib/new_relic/agent/tracer.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/new_relic/agent/tracer.rb b/lib/new_relic/agent/tracer.rb index 4e1b0383e4..e11727e080 100644 --- a/lib/new_relic/agent/tracer.rb +++ b/lib/new_relic/agent/tracer.rb @@ -424,7 +424,7 @@ def thread_block_with_current_transaction(*args, segment_name:, parent: nil, &bl current_txn = ::Thread.current[:newrelic_tracer_state]&.current_transaction if ::Thread.current[:newrelic_tracer_state]&.is_execution_traced? proc do begin - if current_txn + if current_txn && !current_txn.initial_segment.finished? NewRelic::Agent::Tracer.state.current_transaction = current_txn current_txn.async = true segment_name += "/Thread#{::Thread.current.object_id}/Fiber#{::Fiber.current.object_id}" if NewRelic::Agent.config[:'thread_ids_enabled'] From 4512950ff0038be6496e523c2efa74f32782b5e0 Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Fri, 21 Apr 2023 09:11:01 -0700 Subject: [PATCH 2/8] add state reset if segment limit reached on a finished transaction --- lib/new_relic/agent/transaction/tracing.rb | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/lib/new_relic/agent/transaction/tracing.rb b/lib/new_relic/agent/transaction/tracing.rb index 1ed62d462c..00414fa71d 100644 --- a/lib/new_relic/agent/transaction/tracing.rb +++ b/lib/new_relic/agent/transaction/tracing.rb @@ -29,6 +29,11 @@ def add_segment(segment, parent = nil) else segment.record_on_finish = true ::NewRelic::Agent.logger.debug("Segment limit of #{segment_limit} reached, ceasing collection.") + + if initial_segment&.finished? + ::NewRelic::Agent.logger.debug("Transaction #{best_name} has finished but segments still being created, resetting state.") + NewRelic::Agent::Tracer.state.reset + end end segment.transaction_assigned end From 8bd3fe7b5ceb4023dc89bb16081e2b02490d0e3f Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Mon, 24 Apr 2023 16:41:49 -0700 Subject: [PATCH 3/8] add finished? method to transaction --- lib/new_relic/agent/tracer.rb | 2 +- lib/new_relic/agent/transaction/tracing.rb | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/new_relic/agent/tracer.rb b/lib/new_relic/agent/tracer.rb index e11727e080..d1c1979519 100644 --- a/lib/new_relic/agent/tracer.rb +++ b/lib/new_relic/agent/tracer.rb @@ -424,7 +424,7 @@ def thread_block_with_current_transaction(*args, segment_name:, parent: nil, &bl current_txn = ::Thread.current[:newrelic_tracer_state]&.current_transaction if ::Thread.current[:newrelic_tracer_state]&.is_execution_traced? proc do begin - if current_txn && !current_txn.initial_segment.finished? + if current_txn && !current_txn.finished? NewRelic::Agent::Tracer.state.current_transaction = current_txn current_txn.async = true segment_name += "/Thread#{::Thread.current.object_id}/Fiber#{::Fiber.current.object_id}" if NewRelic::Agent.config[:'thread_ids_enabled'] diff --git a/lib/new_relic/agent/transaction/tracing.rb b/lib/new_relic/agent/transaction/tracing.rb index 00414fa71d..3c0cf2f66a 100644 --- a/lib/new_relic/agent/transaction/tracing.rb +++ b/lib/new_relic/agent/transaction/tracing.rb @@ -30,7 +30,7 @@ def add_segment(segment, parent = nil) segment.record_on_finish = true ::NewRelic::Agent.logger.debug("Segment limit of #{segment_limit} reached, ceasing collection.") - if initial_segment&.finished? + if finished? ::NewRelic::Agent.logger.debug("Transaction #{best_name} has finished but segments still being created, resetting state.") NewRelic::Agent::Tracer.state.reset end From 958c584884642901c3c63da1a2788584052eb08a Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Mon, 24 Apr 2023 16:42:07 -0700 Subject: [PATCH 4/8] add finished? to transaction --- lib/new_relic/agent/transaction.rb | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/lib/new_relic/agent/transaction.rb b/lib/new_relic/agent/transaction.rb index ec515c1a32..95b2b43296 100644 --- a/lib/new_relic/agent/transaction.rb +++ b/lib/new_relic/agent/transaction.rb @@ -439,6 +439,10 @@ def initial_segment segments.first end + def finished? + initial_segment.finished? + end + def create_initial_segment(options = {}) segment = create_segment(@default_name, options) segment.record_scoped_metric = false From 427e3205a7ebd1cb7178c01913ee800fab7b9747 Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Mon, 24 Apr 2023 16:46:14 -0700 Subject: [PATCH 5/8] add test for finished transactions not being used in new threads --- test/new_relic/agent/tracer_test.rb | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/test/new_relic/agent/tracer_test.rb b/test/new_relic/agent/tracer_test.rb index b8b3321cac..3686a8a949 100644 --- a/test/new_relic/agent/tracer_test.rb +++ b/test/new_relic/agent/tracer_test.rb @@ -301,6 +301,21 @@ def test_current_segment_without_transaction assert_nil Tracer.current_segment end + def test_traced_threads_dont_keep_using_finished_transaction + txn = Tracer.start_transaction(name: 'Controller/blogs/index', category: :controller) + threads = [] + threads << Thread.new do + segment = Tracer.start_segment(name: 'Custom/MyClass/myoperation') + sleep(0.01) until txn.finished? + + threads << Thread.new do + assert_nil Tracer.current_transaction + end + end + txn.finish + threads.each(&:join) + end + def test_current_segment_in_nested_threads_with_traced_thread assert_nil Tracer.current_segment From a3b52f7d15dc5dc74e9e1e974eff63d09042595a Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Mon, 24 Apr 2023 17:06:18 -0700 Subject: [PATCH 6/8] add suportabillity metric --- lib/new_relic/agent/transaction/tracing.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/new_relic/agent/transaction/tracing.rb b/lib/new_relic/agent/transaction/tracing.rb index 3c0cf2f66a..0a81f4f3e3 100644 --- a/lib/new_relic/agent/transaction/tracing.rb +++ b/lib/new_relic/agent/transaction/tracing.rb @@ -33,6 +33,7 @@ def add_segment(segment, parent = nil) if finished? ::NewRelic::Agent.logger.debug("Transaction #{best_name} has finished but segments still being created, resetting state.") NewRelic::Agent::Tracer.state.reset + NewRelic::Agent.record_metric('Supportability/Transaction/SegmentLimitReachedAfterFinished/ResetState', 1) end end segment.transaction_assigned From b247f2994e618b8e13b49ff55cf498c5e4f2a1e5 Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Mon, 24 Apr 2023 17:06:34 -0700 Subject: [PATCH 7/8] add test for segment limit reach if finished --- test/new_relic/agent/tracer_test.rb | 1 + .../agent/transaction/tracing_test.rb | 26 +++++++++++++++++++ 2 files changed, 27 insertions(+) diff --git a/test/new_relic/agent/tracer_test.rb b/test/new_relic/agent/tracer_test.rb index 3686a8a949..510ef139de 100644 --- a/test/new_relic/agent/tracer_test.rb +++ b/test/new_relic/agent/tracer_test.rb @@ -312,6 +312,7 @@ def test_traced_threads_dont_keep_using_finished_transaction assert_nil Tracer.current_transaction end end + sleep(0.01) until txn.segments.size >= 2 txn.finish threads.each(&:join) end diff --git a/test/new_relic/agent/transaction/tracing_test.rb b/test/new_relic/agent/transaction/tracing_test.rb index 182f3ab58f..0e71ae613c 100644 --- a/test/new_relic/agent/transaction/tracing_test.rb +++ b/test/new_relic/agent/transaction/tracing_test.rb @@ -447,6 +447,32 @@ def test_trace_should_log_segment_limit_reached_once end end + def test_trace_should_reset_state_if_segment_limit_reached_and_transaction_finished + with_config(:'transaction_tracer.limit_segments' => 3) do + txn = Tracer.start_transaction(name: 'Controller/blogs/index', category: :controller) + threads = [] + threads << Thread.new do + segment = Tracer.start_segment(name: 'Custom/MyClass/myoperation') + segment.finish + + assert NewRelic::Agent::Tracer.current_transaction + sleep(0.01) until txn.finished? + segment = Tracer.start_segment(name: 'Custom/MyClass/myoperation2') + segment.finish + segment = Tracer.start_segment(name: 'Custom/MyClass/myoperation3') + segment.finish + segment = Tracer.start_segment(name: 'Custom/MyClass/myoperation4') + segment.finish + + assert_metrics_recorded('Supportability/Transaction/SegmentLimitReachedAfterFinished/ResetState') + assert_nil Tracer.current_transaction + end + sleep(0.01) until txn.segments.size >= 2 + txn.finish + threads.each(&:join) + end + end + def test_threshold_recorded_for_trace with_config(:'transaction_tracer.transaction_threshold' => 2.0) do in_transaction {} From 6883f631046fac19b66222471e8f1eb9a8ffdd3e Mon Sep 17 00:00:00 2001 From: Tanna McClure Date: Tue, 25 Apr 2023 16:07:53 -0700 Subject: [PATCH 8/8] add changelog entry --- CHANGELOG.md | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0ec15aaaa9..afa6240313 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,7 +1,12 @@ # New Relic Ruby Agent Release Notes ## dev - Version ___ fixes a bug preventing errors from being expected. + Version ___ fixes a bug causing the agent to continue storing data on finished transaction, and a bug preventing errors from being expected. + +- **Bugfix: Finished transactions continue to store data on different threads** + + Previously, when a new thread was spawned the agent would continue using the current transaction to record data on, even if this transaction had finished already in a different thread. Now the agent will only use the current transaction in the new thread if it is not yet finished. Thank you to [@fcheung](https://github.com/fcheung) for reporting this bug and providing us with an extremely helpful reproduction to debug. [PR#1969](https://github.com/newrelic/newrelic-ruby-agent/pull/1969) + - **Bugfix: Expected Errors passed to notice_error are expected again**