ActiveSupport Notification Subscribers for ActionController and ActiveRecord Events

config-initializers-action_controller-notifications.rb

unless Rails.env.production?
  ActiveSupport::Notifications.subscribe(/\A.*\.action_controller\z/) do |*args|
    ts = Time.now.iso8601

    event = ActiveSupport::Notifications::Event.new(*args)
    event_name, source_name = event.name.split('.')

    unless event_name == 'unpermitted_parameters'
      log_file = "#{source_name.tr('_', '-')}-notifications.log"
      logger = ActiveSupport::TaggedLogging.new(Logger.new(Rails.root.join('log', log_file)))
      logger.tagged(ts, source_name.upcase, event_name.upcase) do
        logger.debug { "duration=#{event.duration} method=\"#{event.payload[:method]}\" endpoint=\"#{event.payload[:controller]}##{event.payload[:action]}\" format=\"#{event.payload[:format]}\" path=\"#{event.payload[:path]}\"" }
        params = { 'params' => event.payload[:params] }
        logger.ap(params)
      end
    end
  end
end

config-initializers-active_record-notifications.rb

unless Rails.env.production?
  ActiveSupport::Notifications.subscribe(/\A.*\.active_record\z/) do |*args|
    ts = Time.now.iso8601

    event = ActiveSupport::Notifications::Event.new(*args)

    unless event.payload[:name] == 'SCHEMA'
      event_name, source_name = event.name.split('.')

      log_file = "#{source_name.tr('_', '-')}-notifications.log"
      logger = ActiveSupport::TaggedLogging.new(Logger.new(Rails.root.join('log', log_file)))
      logger.tagged(ts, source_name.upcase, event_name.upcase) do
        case event_name
        when 'instantiation'
          logger.debug { "class_name=\"#{event.payload[:class_name]}\" record_count=#{event.payload[:record_count]}" }
        when 'sql'
          logger.debug { "duration=#{event.duration} length=#{event.payload[:sql].length}" }
          sql = { 'sql' => event.payload[:sql] }
          logger.ap(sql)
        end
      end
    end
  end
end

Ugh. I had an entire README.md written up in this gist explaining how this all works but it wasn't saved. :/

In a nutshell. These are basically examples of how to use ActiveSupport::Notification subscribers that are built into Rails. I needed to see how ActiveRecord and ActionController was behaving beyond what the simple and very noise Rails.logger was reporting. I split the gist into two files to make them more readable but they can both be defined in together. For example, config/initializers/notifications.rb. The Rails.env.production? guard is only because these are rough implementations of diagnostic loggers not really tuned for production use. ActiveSupport::Notification is useful for far more than simple logging in production as it's essentially a PUB/SUB system for Rails. :)