roidrage / lograge

An attempt to tame Rails' default policy to log everything.
http://www.paperplanes.de/2012/3/14/on-notifications-logsubscribers-and-bringing-sanity-to-rails-logging.html
MIT License
3.47k stars 300 forks source link

Using custom_payload in an initializer can prevent other gems to lazy setup rails components #302

Open bobmaerten opened 5 years ago

bobmaerten commented 5 years ago

Context

Hi, I have a project using https://github.com/binarylogic/authlogic and I had trouble to get it running in production, because of a railties setup problem: ActionController was required before the authlogic lazy setup could trigger.

Why I think it's lograge related?

Because I checked all my gems by disabling them individually. And when I disable lograge, everything runs fine.

Digging further, I found out that the culprit was an initializer invoking Lograge custom_payload.

demo-app

https://github.com/bobmaerten/authlogic_rails_adapter_loaded_to_late

I've set up an example application which trigger an error with authologic when precompiling production assets with a configured Lograge initializer (same effect when config is placed in config/environment/production.rb)

Running assets precompilation fails:

$ DISABLE_SPRING=1 RAILS_ENV=production bundle exec rails assets:clean assets:precompile
rails aborted!
Authlogic::ControllerAdapters::RailsAdapter::AuthlogicLoadedTooLateError: Authlogic is trying to add a callback to ActionController::Base but ApplicationController has already been loaded, so the callback won't be copied into your application. Generally this is due to another gem or plugin requiring your ApplicationController prematurely, such as the resource_controller plugin. Please require Authlogic first, before these other gems / plugins.
/Users/bob/Work/authlogic_rails_adapted_loaded_to_late/config/environment.rb:5:in `<main>'
bin/rails:9:in `<main>'
Tasks: TOP => environment
(See full trace by running task with --trace)

When removing config/initializers/lograge.rb or block in config/environment/production.rb or even simple usage of config.lograge.custom_payloadfrom those files.

$ DISABLE_SPRING=1 RAILS_ENV=production bundle exec rails assets:clean assets:precompile
yarn install v1.17.3
[1/4] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.41s.

What did I do to make the whole gems work together?

We managed to split the configuration from the initializer to production environment file and ApplicationController by overriding the rails append_info_to_payload method as suggested in the documentation.

# app/controllers/application_controller.rb
class ApplicationController < ActionController::Base
  def append_info_to_payload(payload)
    super
    payload[:host] = request.host
  end
end
# config/initializers/lograge.rb
Rails.application.configure do
  config.lograge.enabled = true

  # add time to lograge
  config.lograge.custom_options = lambda do |event|
    {host:  event.payload[:host]}
  end
end

With this setup, it works. With the documented custom_payload it's not.

Trying to find what is not working

Authlogic just got upgraded to 5.0.3 with a change in its ActionController setup.

I'm not super fluent in railties, but Lograge seems not use the rails setup best practise, and instead juste requiring rails components like this https://github.com/roidrage/lograge/blob/397c830208a7ec1601c0eacc0dddd09274afff5b/lib/lograge/railtie.rb#L1

May be you could replace the code with something like

require "active_support"

ActiveSupport.on_load(:action_controller) do
  # do whatever Lograge need to do
end

or may be just drop the custom_payload example from the documentation?

bobmaerten commented 5 years ago

I talk about the problem with friends and it seems other gems can trigger the same problem though. I'll reference this problem in authlogic repo too.

bobmaerten commented 5 years ago

Seems the boot problem came from old code in authlogic. Nonetheless the part about lazy setup is still relevant.