Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bugfix Thread instrumentation continuing to use finished transactions on other threads #1969

Merged
merged 9 commits into from
Apr 26, 2023
7 changes: 6 additions & 1 deletion CHANGELOG.md
Original file line number Diff line number Diff line change
@@ -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**

Expand Down
2 changes: 1 addition & 1 deletion lib/new_relic/agent/tracer.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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']
Expand Down
4 changes: 4 additions & 0 deletions lib/new_relic/agent/transaction.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
6 changes: 6 additions & 0 deletions lib/new_relic/agent/transaction/tracing.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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.")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This new module code make use of a method, best_name, that doesn't exist in the module, so the code can only be used by an instance of the Transaction class. Seeing as the Transaction class is the only consumer (includer) of this Tracing module, this is probably ok.

NewRelic::Agent::Tracer.state.reset
NewRelic::Agent.record_metric('Supportability/Transaction/SegmentLimitReachedAfterFinished/ResetState', 1)
end
end
segment.transaction_assigned
end
Expand Down
16 changes: 16 additions & 0 deletions test/new_relic/agent/tracer_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
26 changes: 26 additions & 0 deletions test/new_relic/agent/transaction/tracing_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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 {}
Expand Down