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

A NoMethodError is raised with a segment callback set #2213

Closed
toncid opened this issue Sep 14, 2023 · 6 comments · Fixed by #2218
Closed

A NoMethodError is raised with a segment callback set #2213

toncid opened this issue Sep 14, 2023 · 6 comments · Fixed by #2218
Assignees
Labels
2 Story Point Estimate bug community To tag external issues and PRs submitted by the community

Comments

@toncid
Copy link

toncid commented Sep 14, 2023

Description

When the experimental segment callback is set, an unhandled NoMethodError is raised by the agent when a Net::HTTP call happens within a delayed job:

[NoMethodError] undefined method `finish' for nil:NilClass

As this is a local agent error, it does not appear in the New Relic dashboard.

Removing the callback fixes the problem.

Expected Behavior

The exception is prevented and normal execution continues.

Troubleshooting or NR Diag results

Provide any other relevant log data.

Stack trace:

/var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:38:in `ensure in request_with_tracing'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:38:in `request_with_tracing'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/net_http/prepend.rb:15:in `request'
    /var/www/server/lib/fiscal/util.rb:251:in `block in create_transaction'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/net-http-0.3.2/lib/net/http.rb:1238:in `start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/net-http-0.3.2/lib/net/http.rb:687:in `start'
    /var/www/server/lib/fiscal/util.rb:244:in `create_transaction'
    /var/www/server/lib/fiscal/report.rb:9:in `request_report'
    /var/www/server/app/jobs/upload_reports_job.rb:23:in `block in perform'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
    /var/www/server/app/jobs/upload_reports_job.rb:11:in `perform'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/execution.rb:48:in `block in perform_now'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
    /var/www/server/app/jobs/recurring_job.rb:4:in `block in <class:RecurringJob>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/app/jobs/application_job.rb:5:in `block in <class:ApplicationJob>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/active_job.rb:67:in `perform'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/active_job.rb:23:in `block (4 levels) in <main>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/i18n-1.14.1/lib/i18n.rb:322:in `with_locale'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/core_ext/time/zones.rb:66:in `use_zone'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/instrumentation.rb:21:in `block in instrument'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/notifications.rb:203:in `block in instrument'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/notifications.rb:203:in `instrument'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/instrumentation.rb:31:in `instrument'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/instrumentation.rb:14:in `block (2 levels) in <module:Instrumentation>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/logging.rb:24:in `tag_logger'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/logging.rb:15:in `block (2 levels) in <module:Logging>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:137:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/execution.rb:47:in `perform_now'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/execution.rb:25:in `block in execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/railtie.rb:47:in `block (4 levels) in <class:Railtie>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/execution_wrapper.rb:91:in `wrap'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/reloader.rb:72:in `block in wrap'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/execution_wrapper.rb:91:in `wrap'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/reloader.rb:71:in `wrap'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/railtie.rb:46:in `block (3 levels) in <class:Railtie>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:137:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/execution.rb:23:in `execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activejob-6.1.7.4/lib/active_job/queue_adapters/delayed_job_adapter.rb:42:in `perform'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/backend/base.rb:81:in `block in invoke_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:61:in `block in initialize'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:66:in `execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:40:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/backend/base.rb:78:in `invoke_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/delayed_job/prepend.rb:28:in `block in invoke_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/delayed_job/instrumentation.rb:45:in `block in invoke_job_with_tracing'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:383:in `perform_action_with_newrelic_trace'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/delayed_job/instrumentation.rb:44:in `invoke_job_with_tracing'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-9.5.0/lib/new_relic/agent/instrumentation/delayed_job/prepend.rb:28:in `invoke_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:231:in `block (2 levels) in run'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/timeout-0.4.0/lib/timeout.rb:186:in `block in timeout'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/timeout-0.4.0/lib/timeout.rb:193:in `timeout'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:231:in `block in run'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/benchmark-0.2.1/lib/benchmark.rb:311:in `realtime'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:230:in `run'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:313:in `block in reserve_and_run_one_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:61:in `block in initialize'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:66:in `execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:40:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:313:in `reserve_and_run_one_job'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:214:in `block in work_off'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:213:in `times'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:213:in `work_off'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:176:in `block (4 levels) in start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/benchmark-0.2.1/lib/benchmark.rb:311:in `realtime'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:175:in `block (3 levels) in start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:61:in `block in initialize'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:66:in `execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:40:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:174:in `block (2 levels) in start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:173:in `loop'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:173:in `block in start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/plugins/clear_locks.rb:7:in `block (2 levels) in <class:ClearLocks>'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:79:in `block (2 levels) in add'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:61:in `block in initialize'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:79:in `block in add'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:66:in `execute'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/lifecycle.rb:40:in `run_callbacks'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/worker.rb:172:in `start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:137:in `run'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:125:in `block in run_process'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application.rb:277:in `block in start_proc'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/daemonize.rb:84:in `call_as_daemon'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application.rb:281:in `start_proc'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application.rb:307:in `start'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application_group.rb:164:in `block (2 levels) in start_all'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/fork_tracker.rb:10:in `block in fork'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/fork_tracker.rb:8:in `fork'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/fork_tracker.rb:8:in `fork'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/activesupport-6.1.7.4/lib/active_support/fork_tracker.rb:27:in `fork'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application_group.rb:163:in `block in start_all'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application_group.rb:162:in `each'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/application_group.rb:162:in `start_all'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/controller.rb:66:in `run'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons.rb:199:in `block in run_proc'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons/cmdline.rb:124:in `catch_exceptions'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/daemons-1.4.1/lib/daemons.rb:198:in `run_proc'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:123:in `run_process'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:104:in `block in daemonize'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:102:in `times'
    /var/www/server/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.11/lib/delayed/command.rb:102:in `daemonize'
    ./bin/delayed_job:5:in `<main>'
    ...

Steps to Reproduce

  1. Call the experimental NewRelic::Agent::Transaction::ExternalRequestSegment.set_segment_callback(...)
  2. Issue a Net::HTTP request from within a delayed job.

Note: It is possible that the delayed_job part is irrelevant, but this is how I can repro within our project.

Your Environment

Ruby v2.6, Rails v6.1.7.4

Additional context

Possibly related tickets: #1556 and #1923.

For Maintainers Only or Hero Triaging this bug

Suggested Priority (P1,P2,P3,P4,P5): N/A
Suggested T-Shirt size (S, M, L, XL, Unknown): N/A

@toncid toncid added the bug label Sep 14, 2023
@workato-integration
Copy link

@github-actions github-actions bot added the community To tag external issues and PRs submitted by the community label Sep 14, 2023
@kford-newrelic kford-newrelic added estimate Issue needing estimation oct-dec qtr Possible FY Q3 candidate labels Sep 14, 2023
@fallwith
Copy link
Contributor

Hi @toncid,

We're sorry to hear that the callback isn't working out as we'd hoped. There are at least 2 issues you've brought to our attention with this issue that we'll be looking into:

  • We're currently using an ensure block (instrumentation.rb#L38) with a very optimistic assumption that a segment object will always be set. Given that the ensure block is called even after exceptions, we should be guarding against nil by changing segment.finish into segment&.finish.
  • Experimental or not, it shouldn't be possible for a callback's invocation to result in a nil for an attempt to create a segment. We'll look into adding a rescue block or whatnot to effectively guarantee segment creation even when a callback has issues.

Once we roll out those 2 fixes, you should no longer see the agent attempt to call #finish on a nil segment, but they might not fix the root cause.

There may be an issue unexpected issue happening within the callback itself. If you can reproduce the problem with a callback that does not contain any sensitive values or business logic and feel comfortable sharing the callback code, we'll attempt to use it to reproduce and investigate the issue. If not, no worries, we can still proceed.

@fallwith fallwith self-assigned this Sep 15, 2023
@fallwith fallwith removed estimate Issue needing estimation oct-dec qtr Possible FY Q3 candidate labels Sep 15, 2023
@fallwith
Copy link
Contributor

fallwith commented Sep 15, 2023

@toncid the 2 fixes described in my previous comment will be delivered with #2218 via a new callback_fallback branch.

Feel free to test with that branch:

# Gemfile
source "https://rubygems.org"

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

There's a new rescue wrapping the callback call now that will write an ERROR logger statement to newrelic_agent.log. If you end up hitting that rescue and seeing the logger statement, I'd be interested in knowing more about the cause. If you can think of anything else that might help out your situation, do please let us know.

update: #2218 has been merged and the callback_fallback branch has now been deleted. The dev branch should now be used instead.

@toncid
Copy link
Author

toncid commented Sep 15, 2023

Hello @fallwith, this has helped! There was indeed a kind of raise 'kaboom' line in the callback. We have fixed it and reverted back to the released gem.

I would suggest to always run the segment callback with a rescue block and therefore keep the agent operational.

@toncid
Copy link
Author

toncid commented Sep 15, 2023

Thank you for the great support!

@fallwith
Copy link
Contributor

Sure thing, @toncid! I'm glad to hear things are working for you. The new rescue will go out in a future agent release.

@kford-newrelic kford-newrelic added the 2 Story Point Estimate label Sep 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
2 Story Point Estimate bug community To tag external issues and PRs submitted by the community
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

3 participants