search

newrelic / newrelic-ruby-agent

New Relic RPM Ruby Agent
https://docs.newrelic.com/docs/apm/agents/ruby-agent/getting-started/introduction-new-relic-ruby/
Apache License 2.0
1.2k stars 598 forks source link

RPM forces Rails frameworks to load during initialization #662

Closed jdelStrother closed 1 year ago

jdelStrother commented 3 years ago

Description

Loading the newrelic gem causes ActionView::Base, ActiveRecord::Base & ActiveJob::Base to load before config-initialization. Normally this should be deferred to after_initialize.

One particular example: Rails generates a config/initializers/new_framework_defaults_6_1.rb file which configures ActiveRecord settings (eg Rails.application.config.active_record.has_many_inversing = true). However, if ActiveRecord::Base has already loaded, this config has no effect, and any changes to it are silently ignored.

Expected Behavior

ActionView::Base, ActiveRecord::Base & ActiveJob::Base aren't loaded until after config/initializers are processed.

Here's the stack where ActiveRecord is loaded:


/nix/store/666hwyf9pmlq3vw6z9p9lmshbinvwpri-ruby2.7.2-activerecord-6.1.3.1/lib/ruby/gems/2.7.0/gems/activerecord-6.1.3.1/lib/active_record/base.rb:315:in `<module:ActiveRecord>'
/nix/store/666hwyf9pmlq3vw6z9p9lmshbinvwpri-ruby2.7.2-activerecord-6.1.3.1/lib/ruby/gems/2.7.0/gems/activerecord-6.1.3.1/lib/active_record/base.rb:15:in `<main>'
/nix/store/i3zqcq6pzd6bdgvgrf2xrmbb1vnrj8vm-ruby2.7.2-zeitwerk-2.4.2/lib/ruby/gems/2.7.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:34:in `require'
/nix/store/jbxyvfbx31cj67cnin6qfb8969h23qni-ruby2.7.2-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332:in `block in require'
/nix/store/jbxyvfbx31cj67cnin6qfb8969h23qni-ruby2.7.2-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:299:in `load_dependency'
/nix/store/jbxyvfbx31cj67cnin6qfb8969h23qni-ruby2.7.2-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332:in `require'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/database_adapter.rb:9:in `block in <class:DatabaseAdapter>'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/database_adapter.rb:29:in `value'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/database_adapter.rb:16:in `value'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/environment_report.rb:72:in `block in <class:EnvironmentReport>'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/environment_report.rb:97:in `block in initialize'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/environment_report.rb:95:in `each'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/environment_report.rb:95:in `inject'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/environment_report.rb:95:in `initialize'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/agent.rb:806:in `new'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/agent.rb:806:in `environment_for_connect'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/agent.rb:500:in `setup_and_start_agent'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/agent.rb:487:in `check_config_and_start_agent'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/agent.rb:547:in `start'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/control/instance_methods.rb:135:in `start_agent'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/control/instance_methods.rb:75:in `init_plugin'
/nix/store/lw2q489apbl39jwr75ay1l6ccvmha37x-ruby2.7.2-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/newrelic_rpm.rb:41:in `block in <class:Railtie>'
/nix/store/hwzbksca7fcybhbf858r2x55hxz4jrib-ruby2.7.2-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:32:in `instance_exec'
/nix/store/hwzbksca7fcybhbf858r2x55hxz4jrib-ruby2.7.2-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:32:in `run'
/nix/store/hwzbksca7fcybhbf858r2x55hxz4jrib-ruby2.7.2-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:228:in `block in tsort_each'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:431:in `each_strongly_connected_component_from'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:349:in `block in each_strongly_connected_component'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `each'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `call'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `each_strongly_connected_component'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:226:in `tsort_each'
/nix/store/npjg64gz5fvm6nqkliqidwrlhslcmf77-ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:205:in `tsort_each'
/nix/store/hwzbksca7fcybhbf858r2x55hxz4jrib-ruby2.7.2-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:60:in `run_initializers'
/nix/store/hwzbksca7fcybhbf858r2x55hxz4jrib-ruby2.7.2-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/application.rb:384:in `initialize!'
/Users/jon/Developer/web/config/environment.rb:7:in `<top (required)>'

And for ActionView:

/nix/store/z003m7chsm0sxi26wnkw8qrz9jlyfz7s-ruby2.7.3-actionview-6.1.3.1/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.1/lib/action_view/base.rb:279:in `<class:Base>'
/nix/store/z003m7chsm0sxi26wnkw8qrz9jlyfz7s-ruby2.7.3-actionview-6.1.3.1/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.1/lib/action_view/base.rb:141:in `<module:ActionView>'
/nix/store/z003m7chsm0sxi26wnkw8qrz9jlyfz7s-ruby2.7.3-actionview-6.1.3.1/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.1/lib/action_view/base.rb:12:in `<main>'
/nix/store/xdar44kdf326rwxbx7z83sy4lzyy07k9-ruby2.7.3-zeitwerk-2.4.2/lib/ruby/gems/2.7.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:34:in `require'
/nix/store/4r70l5cniklk8c5dplhb5kfzd082niwd-ruby2.7.3-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332:in `block in require'
/nix/store/4r70l5cniklk8c5dplhb5kfzd082niwd-ruby2.7.3-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:299:in `load_dependency'
/nix/store/4r70l5cniklk8c5dplhb5kfzd082niwd-ruby2.7.3-activesupport-6.1.3.1/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332:in `require'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/agent/instrumentation/rails_notifications/action_view.rb:25:in `block (2 levels) in <main>'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:120:in `block in execute'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:118:in `each'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:118:in `execute'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:30:in `block in detect!'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:28:in `each'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/dependency_detection.rb:28:in `detect!'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/control/instrumentation.rb:65:in `_install_instrumentation'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/control/instrumentation.rb:48:in `install_instrumentation'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/new_relic/control/instance_methods.rb:76:in `init_plugin'
/nix/store/1kvns1sj0char9swzqc9qm1q3i9h3chw-ruby2.7.3-newrelic_rpm-7.0.0/lib/ruby/gems/2.7.0/gems/newrelic_rpm-7.0.0/lib/newrelic_rpm.rb:41:in `block in <class:Railtie>'
/nix/store/4zxd5zkhvajadaf07rrvys7jyrrsd7ri-ruby2.7.3-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:32:in `instance_exec'
/nix/store/4zxd5zkhvajadaf07rrvys7jyrrsd7ri-ruby2.7.3-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:32:in `run'
/nix/store/4zxd5zkhvajadaf07rrvys7jyrrsd7ri-ruby2.7.3-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:228:in `block in tsort_each'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:431:in `each_strongly_connected_component_from'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:349:in `block in each_strongly_connected_component'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:347:in `each'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:347:in `call'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:347:in `each_strongly_connected_component'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:226:in `tsort_each'
/nix/store/bqw8cqd6p3b9z23i69fgnhqf3dyppy54-ruby-2.7.3/lib/ruby/2.7.0/tsort.rb:205:in `tsort_each'
/nix/store/4zxd5zkhvajadaf07rrvys7jyrrsd7ri-ruby2.7.3-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:60:in `run_initializers'
/nix/store/4zxd5zkhvajadaf07rrvys7jyrrsd7ri-ruby2.7.3-railties-6.1.3.1/lib/ruby/gems/2.7.0/gems/railties-6.1.3.1/lib/rails/application.rb:384:in `initialize!'
/Users/jon/Developer/web/config/environment.rb:7:in `<top (required)>'

The ActionView one is pretty easy to fix, I think it just needs something like this: https://github.com/jdelStrother/rpm/commit/d6d046e796ee123975022278763cb54540ddc45f

ActiveRecord looks harder, it seems pretty tied into the Agent::DatabaseAdapter bits from a casual glance. One option would be to defer loading of the entire agent until after :load_config_initializers (essentially reverting https://github.com/newrelic/newrelic-ruby-agent/pull/279), but that does seem like it causes problems with adding method_tracers during initialization. Maybe add_method_tracer could be updated to not require a live agent? Or everyone could wrap their add_method_tracer calls in Rails.application.config.after_initialize blocks 😕

angelatan2 commented 3 years ago

Hello @jdelStrother, thank you for submitting this issue. A question to clarify, is this behavior observed with a particular version of the ruby agent?

jdelStrother commented 3 years ago

Hi there - I'm seeing it in 7.0.0.

jdelStrother commented 3 years ago

Any updates on this?

tannalynn commented 3 years ago

Hello @jdelStrother, this is was placed in our next bugsmash, so we will be taking a closer look at this issue when we start work on that milestone. At that time we will look into potential options to address your concerns and decide how we want the agent to handle these scenarios.

amhuntsman commented 3 years ago

@jdelStrother (Note I deleted my previous responses since I misunderstood the problem originally)

I want to make a note for our team on why this is happening:

As also mentioned, moving init_plugin until after configs are loaded is problematic for a couple reasons:

I don't yet have a solution for ActiveRecord/ActiveJob (other than another large refactoring of method tracers), but there are a couple workarounds:

I will get a PR up for at least one of these shortly.

amhuntsman commented 2 years ago

806 was planned to be included in the upcoming release; however, during the release process we uncovered an issue involving initialization load order with a specific gem (roadie-rails in this case). Pending determination of the scope of this problem and whether a fix will require breaking changes to the agent, we are reverting #806 for the release of Ruby Agent 8.1.0.

We apologize for any inconvenience.

cc @jdelStrother

workato-integration[bot] commented 2 years ago

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

kaylareopelle commented 1 year ago

Hi @jdelStrother! I was able to circle back to this bug this week. Thanks for your patience.

We've been able to reproduce the behavior you described with Rails.application.config.active_record.has_many_inversing = true. Our research revealed the problem lies beyond the newrelic_rpm gem and traces back to the Active Record Railtie for 6.1: https://github.com/rails/rails/issues/45683

With the Rails 6.1 code, Active Record configuration values can be set before initializers finish running. The problem is resolved if the Active Record Railtie initializer "active_record.set_configs" is updated to the following:

# activerecord/lib/active_record/railtie.rb:204 on tag for v6.1.0
    initializer "active_record.set_configs" do |app|
      config.after_initialize do # <= This block is missing from Rails 6.1
        ActiveSupport.on_load(:active_record) do
          configs = app.config.active_record
            configs.each do |k, v|
              send "#{k}=", v
            end
        end
      end
    end

The Rails team accepted a fix for this bug that works with Rails 7. Bugfixes for the 6.1.x series are no longer accepted. If your application is not able to upgrade to Rails 7, you could patch your version of Rails to include the code above. We'd be happy to help you do this.

This brings me to a different question: Was the config setting for Rails.application.config.active_record.has_many_inversing an example of the problem or was it the only issue?

We have some ideas to change load order while preserving access to add_method_tracer, but want to make sure our changes solve a reproducible bug.

Thanks for your understanding! I hope to hear from you soon. cc: @sanemat @softbrada

jdelStrother commented 1 year ago

It's just an example of the problem - Rails does not expect ActiveRecord::Base (or any other Rails components) to be loaded before initializers have completed. (There's some more discussion on making this a more obvious error at https://github.com/rails/rails/pull/45297 & https://github.com/rails/rails/pull/44996, though sadly nothing's been merged yet)

Another example is in the upcoming new_framework_defaults_7_1 - https://github.com/rails/rails/blob/main/railties/lib/rails/generators/rails/app/templates/config/initializers/new_framework_defaults_7_1.rb.tt. To pick one as an example, setting Rails.application.config.active_record.run_commit_callbacks_on_first_saved_instances_in_transaction in that file will have no effect if NewRelic is loaded - ActiveRecord::Base.run_commit_callbacks_on_first_saved_instances_in_transaction will remain at its default value.

kaylareopelle commented 1 year ago

Thanks for your response, @jdelStrother! The additional example was very helpful.

I have a branch I'd like you to test to see if it resolves the problem. Could you please update your Gemfile's newrelic_rpm entry to the following: 

gem 'newrelic_rpm', git: 'https://github.com/newrelic/newrelic-ruby-agent.git', branch: 'bugfix/rails-frameworks-forced-to-load-during-agent-initialization'

And let me know how it goes?

In this branch, I've split up the start_plugin initializer into two parts. The first part loads the method tracers API before: :load_config_initializers. The second part contains the rest of the start_plugin code, and runs after: :load_config_initializers.

jdelStrother commented 1 year ago

Looks good!

I did start running into a SystemStackError looking like this - 

/Users/jon/Developer/vendor/rpm/lib/new_relic/agent.rb:495:in `disable_all_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:24:in `request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `request_with_newrelic_trace'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:9:in `block in request'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:8:in `request'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `block in request_with_newrelic_trace'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:26:in `block (2 levels) in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/tracer.rb:355:in `capture_segment_error'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:25:in `block in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent.rb:501:in `disable_all_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:24:in `request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `request_with_newrelic_trace'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:9:in `block in request'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:8:in `request'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `block in request_with_newrelic_trace'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:26:in `block (2 levels) in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/tracer.rb:355:in `capture_segment_error'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:25:in `block in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent.rb:501:in `disable_all_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:24:in `request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `request_with_newrelic_trace'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:9:in `block in request'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:8:in `request'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `block in request_with_newrelic_trace'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:26:in `block (2 levels) in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/tracer.rb:355:in `capture_segment_error'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:25:in `block in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent.rb:501:in `disable_all_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:24:in `request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `request_with_newrelic_trace'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:9:in `block in request'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:8:in `request'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `block in request_with_newrelic_trace'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:26:in `block (2 levels) in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/tracer.rb:355:in `capture_segment_error'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:25:in `block in request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent.rb:501:in `disable_all_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/instrumentation.rb:24:in `request_with_tracing'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `request_with_newrelic_trace'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:9:in `block in request'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/mini_profiler/profiling_methods.rb:46:in `step'
/Users/jon/Developer/web/vendor/bundle/ruby/3.1.0/gems/rack-mini-profiler-3.0.0/lib/patches/net_patches.rb:8:in `request'
/Users/jon/Developer/vendor/rpm/lib/new_relic/agent/instrumentation/net_http/chain.rb:15:in `block in request_with_newrelic_trace'

which appears to be a conflict with rack-mini-profiler's prepend_net_http_patch which surfaced with the load order changes. However, it seems like I can just remove our require "prepend_net_http_patch" and everything behaves as expected.

kaylareopelle commented 1 year ago

Hi @jdelStrother, thanks for the feedback!

Given there's a chance the initialization change may interfere with existing initializers, we decided to place the fix inside a configuration option, defer_rails_initialization. This will default to false in 8.14.0 until we can see how it impacts more customer environments.

In 8.14.0 (and if you're using the branch on its latest commit), defer_rails_initialization will need to be set to true to prevent ActiveRecord from loading before config/initializers is run.

jdelStrother commented 1 year ago

Thanks, will try it out once 8.14 is out

fallwith commented 1 year ago

Hi @jdelStrother, version 8.14.0 of the newrelic_rpm has now been released. Thank you again for bringing this issue to our attention. We have also recognized you as having done so in our CHANGELOG. Much appreciated!

jdelStrother commented 1 year ago

Ugh, sorry - I don't think this fix works.

By this point - https://github.com/newrelic/newrelic-ruby-agent/blob/fec78e8d48900321ac6d22c2d79908025402c81f/lib/newrelic_rpm.rb#L23 - NewRelic hasn't loaded any configuration off-disk, it's entirely relying on the config in DefaultSource. So adding defer_rails_initialization to newrelic.yml has no effect.

kaylareopelle commented 1 year ago

@jdelStrother, you so right. I deeply apologize for this oversight. Thank you for giving us a heads up.

Looking back, I ran my final tests on an earlier version of the bugfix branch, not the one with the config. 🤦‍♀️

Our team will need to sort out the best response to get this fix into a release.

In the meantime, I've updated the bugfix/rails-frameworks-forced-to-load-during-agent-initialization branch to make the fix accessible and merged in the rest of the 8.14.0 changes. Feel free to use it.

We'll be back soon with more information.

Code snippet to use this branch if anyone needs it. Replace the gem 'newrelic_rpm' line in your Gemfile with the following: 

gem 'newrelic_rpm', git: 'https://github.com/newrelic/newrelic-ruby-agent.git', branch: 'bugfix/rails-frameworks-forced-to-load-during-agent-initialization'
workato-integration[bot] commented 1 year ago

Work has been completed on this issue.

kaylareopelle commented 1 year ago

Hi @jdelStrother, we have a branch ready for testing that enables this feature using an environment variable instead of a YAML-based config.

The branch is called bugfix/rails-init-env-toggle

To use the split initialization process, set NEW_RELIC_DEFER_RAILS_INITIALIZATION=true.

jdelStrother commented 1 year ago

Looks good from the initialization-order point of view, though I did have to add NEW_RELIC_INSTRUMENTATION_NET_HTTP=prepend to avoid stackoverflow errors with both rack-mini-profiler and sentry. Previously, leaving that config unset (presumably using the default value of "auto") has worked ok.

tannalynn commented 1 year ago

@jdelStrother Interesting, I suspect it's because we have a check in our net http instrumentation that will install chain if rack mini profiler is defined, because it uses method chaining. Perhaps because of the change in when the agent is installing instrumentation now, Rack::MiniProfiler is now loaded before the agent runs those checks, and previously it was checking prior to rack mini profiler being loaded. Since rack miniprofiler does have a prepend patch that can optionally be required, I added an additional check when we're checking for prepend conflicts so that it will no longer always install chain instrumentation is rack miniprofiler is installed, it should now only install chain if the prepend patch constant isn't defined when the agent is loaded. Hopefully this will help prevent that from happening in the future!

tannalynn commented 1 year ago

closed by PR https://github.com/newrelic/newrelic-ruby-agent/pull/1791