Exception due to running before process_action.action_controller event has finished

[felixbuenemann]

I'm seeing crashes when using this gem with rails 4.2.7.1 and it looks like the gem's process_action method gets called before (inside) the one from ActionController::Metal, so the event is not finished yet and tried to get its duration crashes with TypeError (can't convert nil into an exact number), because the @end ivar of the event is nil.

I'm using Puma as a web server and the exception happens in Rails production mode.

If you look at the stack trace below, it looks like ActionController::Metal::Instrumentation.process_action is called which calls this gems process_action method as its super method while still inside the ActiveSupport::Notifications.instrument("process_action.action_controller") block, so the event is not finished yet.

I think this might be a load order dependent problem, because all modules in ActionController get autoloaded, so this could probably be fixed by causing access to the constant in the ActiveSupport.on_load hook of the railtie.

TypeError (can't convert nil into an exact number):
  gems/activesupport-4.2.7.1/lib/active_support/core_ext/time/calculations.rb:233:in `-'
  gems/activesupport-4.2.7.1/lib/active_support/core_ext/time/calculations.rb:233:in `minus_with_duration'
  gems/activesupport-4.2.7.1/lib/active_support/core_ext/time/calculations.rb:244:in `minus_with_coercion'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:61:in `duration'
  gems/rails_server_timings-1.0.7/lib/rails_server_timings/controller_runtime.rb:15:in `block in process_action'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/fanout.rb:127:in `finish'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/fanout.rb:46:in `block in finish'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/fanout.rb:46:in `each'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/fanout.rb:46:in `finish'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:36:in `finish'
  gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:25:in `instrument'
  gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in `instrument'
  gems/actionpack-4.2.7.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  gems/actionpack-4.2.7.1/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
  gems/activerecord-4.2.7.1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  gems/rails_server_timings-1.0.7/lib/rails_server_timings/controller_runtime.rb:22:in `block in process_action'
  gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:176:in `subscribed'
  gems/rails_server_timings-1.0.7/lib/rails_server_timings/controller_runtime.rb:21:in `process_action'
  gems/actionpack-4.2.7.1/lib/abstract_controller/base.rb:137:in `process'
  gems/actionview-4.2.7.1/lib/action_view/rendering.rb:30:in `process'
  gems/actionpack-4.2.7.1/lib/action_controller/metal.rb:196:in `dispatch'
  gems/actionpack-4.2.7.1/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
  gems/actionpack-4.2.7.1/lib/action_controller/metal.rb:237:in `block in action'