Merge pull request #1969 from newrelic/thread_instrumentation_no_txn_…

…if_finished

Bugfix Thread instrumentation continuing to use finished transactions on other threads

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**
 

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.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']

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

lib/new_relic/agent/transaction/tracing.rb

@@ -29,6 +29,12 @@ 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 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
         end

test/new_relic/agent/tracer_test.rb

@@ -301,6 +301,22 @@ 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
+        sleep(0.01) until txn.segments.size >= 2
+        txn.finish
+        threads.each(&:join)
+      end
+
       def test_current_segment_in_nested_threads_with_traced_thread
         assert_nil Tracer.current_segment
 

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 {}