Instrumentation feature causes internal exception inside `newrelic_rpm`

[bjeanes]

There are two distinct exceptions I am seeing on every (Rodauth) request:

Start:

Processing by Authentication::RodauthConfig#call as HTML
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : Error during start callback for event 'process_action.action_controller':
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : NoMethodError: undefined method `controller_path' for Authentication::RodauthConfig:Class
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : Debugging backtrace:
/app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-8.4.0/lib/new_relic/agent/instrumentation/action_controller_subscriber.rb:76:in `format_metric_name'
  /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-8.4.0/lib/new_relic/agent/instrumentation/action_controller_subscriber.rb:51:in `start_transaction_or_segment'
  /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-8.4.0/lib/new_relic/agent/instrumentation/action_controller_subscriber.rb:19:in `start'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:153:in `start'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:59:in `block in start'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:59:in `each'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:59:in `start'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/instrumenter.rb:36:in `start'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/instrumenter.rb:22:in `instrument'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications.rb:203:in `instrument'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/instrumentation.rb:39:in `rails_instrument_request'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/internal_request.rb:31:in `rails_instrument_request'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/instrumentation.rb:8:in `_around_rodauth'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:140:in `block (2 levels) in route'
  /app/vendor/bundle/ruby/2.7.0/gems/roda-3.53.0/lib/roda/request.rb:562:in `if_match'
  /app/vendor/bundle/ruby/2.7.0/gems/roda-3.53.0/lib/roda/request.rb:169:in `is'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:138:in `block in route'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth/features/base.rb:157:in `route!'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:393:in `rodauth'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/app.rb:60:in `rodauth'

Finish:

Completed 200 OK in 48ms (Views: 33.3ms | ActiveRecord: 0.0ms | Allocations: 11875)
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : Error during finish callback for event 'process_action.action_controller':
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : NoMethodError: undefined method `finish' for nil:NilClass
[2022-06-20 06:37:30 +0000 rails-app-ggav9s-6554cc8fcf-tzfzm (6)] ERROR : Debugging backtrace:
/app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-8.4.0/lib/new_relic/agent/instrumentation/action_controller_subscriber.rb:41:in `finish'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:157:in `finish'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:63:in `block in finish'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:63:in `each'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/fanout.rb:63:in `finish'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/instrumenter.rb:45:in `finish_with_state'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/instrumenter.rb:30:in `ensure in instrument'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications/instrumenter.rb:30:in `instrument'
  /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.6/lib/active_support/notifications.rb:203:in `instrument'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/instrumentation.rb:39:in `rails_instrument_request'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/internal_request.rb:31:in `rails_instrument_request'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/feature/instrumentation.rb:8:in `_around_rodauth'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:140:in `block (2 levels) in route'
  /app/vendor/bundle/ruby/2.7.0/gems/roda-3.53.0/lib/roda/request.rb:562:in `if_match'
  /app/vendor/bundle/ruby/2.7.0/gems/roda-3.53.0/lib/roda/request.rb:169:in `is'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:138:in `block in route'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth/features/base.rb:157:in `route!'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-2.21.0/lib/rodauth.rb:393:in `rodauth'
  /app/vendor/bundle/ruby/2.7.0/gems/rodauth-rails-1.2.2/lib/rodauth/rails/app.rb:60:in `rodauth'

I am not on the latest versions of either newrelic_rpm nor rodauth-rails, but looking at the code of both, I don't believe it will make a material difference to this issue.

In rodauth-rails, the rodauth config class name is passed as the controller in the instrumentation payload: https://github.com/janko/rodauth-rails/blob/5a5f0a207663522cf428f5e32617a7f0257ee446/lib/rodauth/rails/feature/instrumentation.rb#L35

In newrelic_rpm, string values for this key are Object.const_get'd and the code expects it to comply with the ActionController::Base interface (in particular, to respond to ActionController::Base.controller_path):

def format_metric_name(metric_action, controller)
  controller_class = controller.is_a?(Class) ? controller : Object.const_get(controller)
  "Controller/#{controller_class.controller_path}/#{metric_action}"
end

That newrelic_rpm constantizes the string is debateable, but its expectation that Rails' instrumentation feature's controller key is a reference to a valid Rails controller is not unreasonable. Should instead the scope class be passed as another key and rails_controller.name be sent for the controller key?

I am not sure about the finish-related exception, but I assume it's either caused by the same issue or a similar issue where the values in the instrumentation payload are not actually valid.

What do you think @janko?

[janko]

Thanks for the report. The main reason the instrumentation integration is passing Rodauth app as :controller (and "call" as :action) is to get the log subscriber to print out Processing by RodauthApp#call, which I believe helps people orient by communicating what is handling the request. It's indeed valid for newrelic_rpm to assume this is a Rails controller, so I'm not sure how to reconcile these two.

I will take a look at the finish-related exception.

[bjeanes]

Thanks @janko! It's 5pm here so I'm about to go offline but if you need any more info, I'll get it to you tomorrow. ✌🏻

[janko]

Should instead the scope class be passed as another key and rails_controller.name be sent for the controller key?

Just saw your suggestion, it sounds interesting 🤔. It probably wouldn't be entirely accurate, since the Rodauth controller isn't actually processing the request, it's only rendering templates and executing callbacks. However, it might be worth stretching the truth.

[bjeanes]

Yeah... tricky. It would at least I think address the Processing by ... use case enough to help orient people.