NewRelic Warning

[tonyta]

Rails Initializers

The following ruby outputs the grepped initializers in the order that they are tsorted in:

$ export initializers='puts Rails.application.initializers.tsort.map(&:name).grep(/load_config|newrelic|heroku/).uniq'

It's run below using Rails runner:

$ bin/rails runner "$initializers"
newrelic_rpm.start_plugin
load_config_initializers

Expected Behavior

When adding newrelic_rpm with a config and a method tracer to a new Rails project (b1f6196), the initializers run as expected.

$ git checkout b1f6196

$ RAILS_ENV=production DISABLE_SPRING=true NEW_RELIC_LOG=stdout bin/rails runner "$initializers"
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Starting the New Relic agent version 4.7.0.339 in "production" environment.
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : To prevent agent startup add a NEW_RELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Reading configuration from config/newrelic.yml (/Users/tonyta/Reflektive/newrelic_warning)
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Environment: production
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : No known dispatcher detected.
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Application: My Application
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] WARN : No license key found. This often means your newrelic.yml file was not found, or it lacks a section for the running environment, 'production'. You may also want to try linting your newrelic.yml to ensure it is valid YML.
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing ActiveRecord 4 instrumentation
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing Rails 3+ middleware instrumentation
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing Net instrumentation
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing deferred Rack::Builder instrumentation
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing Rack::Builder middleware instrumentation
** [NewRelic][2017-12-22 15:05:15 -0800 tta-mac.local (14939)] INFO : Installing Rails 4 Controller instrumentation
** [NewRelic][2017-12-22 15:05:16 -0800 tta-mac.local (14939)] INFO : Installing Rails 4 view instrumentation
** [NewRelic][2017-12-22 15:05:16 -0800 tta-mac.local (14939)] INFO : Finished instrumentation
newrelic_rpm.start_plugin
load_config_initializers

NewRelic's initializer, newrelic_rpm.start_plugin, runs before Rails loads the initialization files.

Reproduced Error

When adding another gem that inserts an initializer that is configured to run after load_config_initializers (such as heroku_rails_deflate) NewRelic's initializer is sorted after load_config_initializers.

$ git checkout 49a3109

$ RAILS_ENV=production DISABLE_SPRING=true NEW_RELIC_LOG=stdout bin/rails runner "$initializers"
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] WARN : Agent unavailable as it hasn't been started.
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] WARN : /Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/newrelic_rpm-4.7.0.339/lib/new_relic/supportability_helper.rb:60:in `record_api_supportability_metric'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/newrelic_rpm-4.7.0.339/lib/new_relic/agent/method_tracer.rb:295:in `add_method_tracer'
/Users/tonyta/Reflektive/newrelic_warning/config/initializers/rpm_instrumentation.rb:5:in `<class:Foo>'
/Users/tonyta/Reflektive/newrelic_warning/config/initializers/rpm_instrumentation.rb:3:in `<top (required)>'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-4.1.16/lib/active_support/dependencies.rb:241:in `load'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-4.1.16/lib/active_support/dependencies.rb:241:in `block in load'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-4.1.16/lib/active_support/dependencies.rb:232:in `load_dependency'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-4.1.16/lib/active_support/dependencies.rb:241:in `load'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/engine.rb:648:in `block in load_config_initializer'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/activesupport-4.1.16/lib/active_support/notifications.rb:161:in `instrument'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/engine.rb:647:in `load_config_initializer'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/engine.rb:612:in `block (2 levels) in <class:Engine>'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/engine.rb:611:in `each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/engine.rb:611:in `block in <class:Engine>'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:30:in `instance_exec'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:30:in `run'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:55:in `block in run_initializers'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:228:in `block in tsort_each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:431:in `each_strongly_connected_component_from'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:44:in `each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:44:in `tsort_each_child'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:415:in `call'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:415:in `each_strongly_connected_component_from'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:349:in `block in each_strongly_connected_component'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:347:in `each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:347:in `call'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:347:in `each_strongly_connected_component'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:226:in `tsort_each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/2.3.0/tsort.rb:205:in `tsort_each'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/initializable.rb:54:in `run_initializers'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/application.rb:300:in `initialize!'
/Users/tonyta/Reflektive/newrelic_warning/config/environment.rb:5:in `<top (required)>'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/application.rb:276:in `require'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/application.rb:276:in `require_environment!'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands/runner.rb:52:in `<top (required)>'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands/commands_tasks.rb:128:in `require'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands/commands_tasks.rb:128:in `require_command!'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands/commands_tasks.rb:95:in `runner'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands/commands_tasks.rb:40:in `run_command!'
/Users/tonyta/.rbenv/versions/2.3.3/lib/ruby/gems/2.3.0/gems/railties-4.1.16/lib/rails/commands.rb:17:in `<top (required)>'
bin/rails:9:in `require'
bin/rails:9:in `<main>'
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Starting the New Relic agent version 4.7.0.339 in "production" environment.
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : To prevent agent startup add a NEW_RELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Reading configuration from config/newrelic.yml (/Users/tonyta/Reflektive/newrelic_warning)
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Environment: production
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : No known dispatcher detected.
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Application: My Application
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] WARN : No license key found. This often means your newrelic.yml file was not found, or it lacks a section for the running environment, 'production'. You may also want to try linting your newrelic.yml to ensure it is valid YML.
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing ActiveRecord 4 instrumentation
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing Rails 3+ middleware instrumentation
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing Net instrumentation
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing deferred Rack::Builder instrumentation
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing Rack::Builder middleware instrumentation
** [NewRelic][2017-12-22 15:05:35 -0800 tta-mac.local (15002)] INFO : Installing Rails 4 Controller instrumentation
** [NewRelic][2017-12-22 15:05:36 -0800 tta-mac.local (15002)] INFO : Installing Rails 4 view instrumentation
** [NewRelic][2017-12-22 15:05:36 -0800 tta-mac.local (15002)] INFO : Finished instrumentation
load_config_initializers
heroku_rails_deflate.middleware_initialization
newrelic_rpm.start_plugin

Now, newrelic_rpm.start_plugin now runs after load_config_initializers, which causes an error since the NewRelic agent has not been initialized when the method tracer is defined.

Fix

When newrelic_rpm is patched, specifying the plugin to be initialized before load_config_intializers (d2bca68), the problem is fixed.

diff --git a/lib/newrelic_rpm.rb b/lib/newrelic_rpm.rb
index 1dbdf1c4d..99260e7fe 100644
--- a/lib/newrelic_rpm.rb
+++ b/lib/newrelic_rpm.rb
@@ -37,7 +37,7 @@ elsif defined?(Rails::VERSION)
     module NewRelic
       class Railtie < Rails::Railtie
 
-        initializer "newrelic_rpm.start_plugin" do |app|
+        initializer "newrelic_rpm.start_plugin", before: :load_config_initializers do |app|
           NewRelic::Control.instance.init_plugin(:config => app.config)
         end
       end

$ git checkout d2bca68

$ RAILS_ENV=production DISABLE_SPRING=true NEW_RELIC_LOG=stdout bin/rails runner "$initializers"
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Starting the New Relic agent version 4.7.1 in "production" environment.
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : To prevent agent startup add a NEW_RELIC_AGENT_ENABLED=false environment variable or modify the "production" section of your newrelic.yml.
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Reading configuration from config/newrelic.yml (/Users/tonyta/Reflektive/newrelic_warning)
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Environment: production
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : No known dispatcher detected.
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Application: My Application
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] WARN : No license key found. This often means your newrelic.yml file was not found, or it lacks a section for the running environment, 'production'. You may also want to try linting your newrelic.yml to ensure it is valid YML.
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing ActiveRecord 4 instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing Rails 3+ middleware instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing Net instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing deferred Rack::Builder instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing Rack::Builder middleware instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing Rails 4 Controller instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Installing Rails 4 view instrumentation
** [NewRelic][2017-12-22 16:12:10 -0800 tta-mac.local (19633)] INFO : Finished instrumentation
newrelic_rpm.start_plugin
load_config_initializers
heroku_rails_deflate.middleware_initialization

The plugin is correctly loaded before load_config_initializers and no warning is displayed.