Upgrading from V8 to V9 causes transactions with custom names to disappear in UI and errors in the logs

[NielsKSchjoedt]

I'm in the process of upgrading a large Rails 6.2 app running APM 8.16 to version 9.0.

In the transactions interface on some web transactions (seems to be the ones with custom transaction names) I see now that most time is attributed to a segment by the name #. What is this and why?

In the newrelic.log I can see the following:

[2023-03-06 15:13:18 +0100 web-01 (1107039)] ERROR : Exception during Transaction#finish
[2023-03-06 15:13:18 +0100 web-01 (1107039)] ERROR : NoMethodError: undefined method `name' for nil:NilClass
[2023-03-06 15:13:18 +0100 web-01 (1107039)] DEBUG : Debugging backtrace:
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction/abstract_segment.rb:267:in `force_finish'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction/abstract_segment.rb:91:in `finalize'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction/tracing.rb:52:in `block in finalize_segments'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction/tracing.rb:52:in `each'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction/tracing.rb:52:in `finalize_segments'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction.rb:555:in `commit!'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/transaction.rb:534:in `finish'
/home/app/a/shared/bundle/ruby/2.7.0/gems/newrelic_rpm-9.0.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:111:in `call'
/home/app/a/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/lib/unicorn/http_server.rb:634:in `process_client'
/home/app/a/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/lib/unicorn/http_server.rb:732:in `worker_loop'
/home/app/a/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
/home/app/a/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/lib/unicorn/http_server.rb:144:in `start'
/home/app/a/shared/bundle/ruby/2.7.0/gems/unicorn-5.8.0/bin/unicorn:128:in `<top (required)>'
/home/app/a/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `load'
/home/app/a/shared/bundle/ruby/2.7.0/bin/unicorn:23:in `<top (required)>'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli/exec.rb:63:in `load'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli/exec.rb:63:in `kernel_load'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli/exec.rb:28:in `run'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli.rb:481:in `exec'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli.rb:31:in `dispatch'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/cli.rb:25:in `start'
/home/app/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/bundler-2.2.25/exe/bundle:49:in `block in <top (required)>'
/home/app/.rbenv/versions/2.7.2/lib/ruby/site_ruby/2.7.0/bundler/friendly_errors.rb:128:in `with_friendly_errors'
/home/app/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/bundler-2.2.25/exe/bundle:37:in `<top (required)>'
/home/app/.rbenv/versions/2.7.2/bin/bundle:23:in `load'
/home/app/.rbenv/versions/2.7.2/bin/bundle:23:in `<main>'

The custom naming in rails controller looks like this:

NewRelic::Agent.set_transaction_name("#{NewRelic::Agent.get_transaction_name} - search_backend: #{resolver.backend}")

I can see here that it seems to be parent which is nil

newrelic-ruby-agent/lib/new_relic/agent/transaction/abstract_segment.rb

Line 267 in 68a3405

"parent #{parent.name} in #{transaction.best_name} may be inaccurate.")

- How can I further debug this and what might be causing it and could it be related?

[workato-integration]

https://issues.newrelic.com/browse/NEWRELIC-7218

[NielsKSchjoedt]

This is how it looks in V8

So it looks like it's the postgresql instrumentation part missing actually

[kaylareopelle]

Thanks for reaching out and putting together such a great bug report, @NielsKSchjoedt! This is concerning behavior.

• When you say, "This is how is looks on V8", is that version 8.16.0, or another 8.x version?
• From your screenshots, I'm seeing the Postgres being less specific in 9.0 than in 8.x. It also seems like the partials and views are missing entirely from 9.0. Do you see partials and views listed in 9.0 for transactions without custom names? Are they present for transactions with custom names?

When encountering problems like this, I like to run the agent with debug-level logs and audit logs turned on and repeat the same behavior in both versions of the agent.

To do this, update your configuration in newrelic.yml to set:

log_level: debug
audit_log.enabled: true

When you have the logs, I'd look for:

• newrelic_agent.log: additional errors, warnings, or other output related to transactions
• newrelic_audit.log: the unique data transferred based on the agent version

These logs can be really verbose, so I wouldn't recommend leaving this configuration when you're not actively debugging.

This bug also sounds like a great candidate to work on through New Relic Support.

You can engage the New Relic Support Community or open a support ticket, depending on your support level. If you choose to go this route, please provide a link to this GitHub issue when submitting your community post or support ticket.

If you prefer to continue collaborating here, that's fine too! 😄

[kaylareopelle]

Hi @NielsKSchjoedt, one more thing -- newrelic_agent.log and newrelic_audit.log can contain sensitive information.

🚨 Please do not post these files directly to GitHub. 🚨

If you choose to post any code snippets, please make sure sensitive information is redacted.

[boomer196]

Experiencing the same issue with 9.0.0. We are coming from 8.16.0.

https://forum.newrelic.com/s/hubtopic/aAX8W0000008eoaWAA/ruby-agent-has-nomethoderror-during-transactionfinish

[kaylareopelle]

Thanks @boomer196 for linking the two issues!

We think the problem might be with our instrumentation for Fibers introduced in the 9.0 release.

Could you try disabling the Fiber instrumentation and let us know if the problem persists?

To disable the instrumentation in your newrelic.yml, add:

instrumentation.fiber: disabled 

To disable the instrumentation using an environment variable add:
NEW_RELIC_INSTRUMENTATION_FIBER=disabled

cc @NielsKSchjoedt

[boomer196]

Could you try disabling the Fiber instrumentation and let us know if the problem persists?

To disable the instrumentation in your newrelic.yml, add:

instrumentation.fiber: disabled 

@kaylareopelle, I disabled the fiber instrumentation as you suggested and the problem still occurs for us. As a side note do not use any custom names. Our implementation is basically out of the box defaults.

[kaylareopelle]

Thanks for the follow-up, @boomer196! I'll keep searching for a solution.

It sounds like you're using a Rails app. Which version are you on? Is your Ruby version 3.2? (it seems like this from the logs in the Explorer's Hub post)

[boomer196]

Thanks for the follow-up, @boomer196! I'll keep searching for a solution.

It sounds like you're using a Rails app. Which version are you on? Is your Ruby version 3.2? (it seems like this from the logs in the Explorer's Hub post)

Yes @kaylareopelle, we are running [email protected] with [email protected]

[kaylareopelle]

I have another config I'd like you to try, @boomer196. Could you turn off thread tracing?

instrumentation.thread.tracing: false 

Turning this off in a sandbox environment with a similar error seemed to stop the problem.

[boomer196]

@kaylareopelle, setting instrumentation.thread.tracing: false appears to have stopped the problem for us as well.

[kaylareopelle]

Thank you, @boomer196. This helps us narrow down which PRs may have introduced the bug! I'm going to do a bit more tinkering and will reach out with a bug fix branch when ready.

[kaylareopelle]

Hi @NielsKSchjoedt, @boomer196 - I have a bug fix branch I'd like you both to test out. It resolves the raised error, but I'm not sure if it'll solve the segments named #.

To install it, please replace your current installation of newrelic_rpm in your Gemfile with:

gem 'newrelic_rpm', git: 'https://github.com/newrelic/newrelic-ruby-agent.git', branch: 'bugfix/transaction_finish_nil_parent'

We'd also like you to turn thread instrumentation back on while testing. To do this, you can either change the value of instrumentation.thread.tracing to true or remove the instrumentation.thread.tracing line from your config.

[kaylareopelle]

@NielsKSchjoedt, we looked further into the way segments are reporting with Threads and noticed the # segments weren't present when using the "New view" for transactions. Threads in Ruby have been introduced since the new view was rolled out, so the old view doesn't have the same support for these types of segments.

When running in a sandbox Rack application that generates one thread per request, this is what we see in the old transaction view:

And here's what we see in the new transaction view:

In the bottom left corner of the graph, you can see Ruby/Thread and the segment is called Ruby/Thread in the table.

Since thread instrumentation was turned on automatically in 9.0, this seems like the reason why upgrading changed the segment names. Thread instrumentation is optional. You can disable it, as mentioned above, by adding to your newrelic.yml:

# newrelic.yml
instrumentation.thread.tracing: false 

[boomer196]

Hi @NielsKSchjoedt, @boomer196 - I have a bug fix branch I'd like you both to test out. It resolves the raised error, but I'm not sure if it'll solve the segments named #.

@kaylareopelle, it did solve the raised error, but not the warnings.

It appears to happen for all of our controller actions. Here is an example of the logged WARN:

** [NewRelic][2023-03-13 21:51:40 +0000 web.1 (57)] WARN : Segment: Controller/Rack/Titan::Application/call was unfinished at the end of transaction. Timing information for this segment's parent in Controller/store/product_detail_pages/show may be inaccurate.

• Do you have any idea why these warnings are being logged?

[kaylareopelle]

@boomer196 - These warnings are most likely logged because an asynchronous process was running when the transaction completed. In this case the segment didn't finish through the standard path, but through a forced finish. The forced finish code path logs this warning.

This is a bit of technical debt around our asynchronous segment timing we've discussed, but have not addressed because we were uncertain about what solution would be beneficial for our customers.

I turned my notes on the team's prior discussions into this issue: #1884

What would you like to happen in this scenario?

[boomer196]

@kaylareopelle, thanks for opening that other issue. I will move over to #1884 to discuss desired behavior. As far as the exception we were seeing, it appears that by adding the Safe Navigation Operator that you did in your bugfix branch, you have fixed the exception. I will bow out of this issue for now as I think we are going to just move up to v9.0.0, so we can keep current, but just disable thread.tracing until other issue is resolved. Thanks for your help.

[fallwith]

The changes provided by #1876 have been released in v9.1.0 of the newrelic_rpm gem.