improved_controller_logging.rb

#
# Ideas stolen from lograge and brought to Rails 2.3
# https://github.com/mattmatt/lograge/blob/master/lib/lograge/log_subscriber.rb
#

module ImprovedControllerLogging
  def self.included(base)
    base.alias_method_chain :log_processing, :fixup
    base.inject_alias_method_chain :perform_action,
      :perform_action_with_benchmark,
      :perform_action_with_fixed_benchmark
  end

  def log_processing_with_fixup
    # We aren't going to log at the start of the request
  end

  def perform_action_with_fixed_benchmark
    if logger
      parameters = respond_to?(:filter_parameters) ? filter_parameters(params) : params.dup
      parameters = parameters.except('controller', 'action', 'format', '_method', 'protocol')

      payload = {
        :controller => self.class.name,
        :action     => self.action_name,
        :params     => parameters,
        :format     => request.format.to_sym,
        :method     => request.method,
        :path       => (request.fullpath rescue "unknown"),
        :remote_ip  => request.remote_ip,
      }

      # Disable this because it doesn't work with newrelic
      if false && GC.respond_to?(:allocated_size)
        initial_allocated_size = GC.allocated_size
      end

      if ObjectSpace.respond_to?(:allocated_objects)
        initial_allocated_objects = ObjectSpace.allocated_objects
      end

      t0 = Time.now
      begin
        perform_action_without_benchmark
      rescue Exception => e
        payload[:duration]  = (Time.now - t0) * 1000
        payload[:status]    = status_code_for_exception(e)
        payload[:exception] = e

        improved_log_action(payload)
        raise
      end

      payload[:duration] = (Time.now - t0) * 1000
      payload[:status] = response.status.to_s[0..2]

      if response.location
        payload[:location] = response.location
      end

      logging_view          = defined?(@view_runtime)
      logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?

      if logging_active_record
        db_runtime = ActiveRecord::Base.connection.reset_runtime
        db_runtime += @db_rt_before_render if @db_rt_before_render
        db_runtime += @db_rt_after_render if @db_rt_after_render

        payload[:db_runtime] = db_runtime.to_i
      end

      if logging_view
        payload[:view_runtime] = @view_runtime.to_i
      end

      if initial_allocated_size
        payload[:change_in_allocated_size] = GC.allocated_size - initial_allocated_size
      end

      if initial_allocated_objects
        payload[:change_in_allocated_objects] = ObjectSpace.allocated_objects - initial_allocated_objects
      end

      improved_log_action(payload)
    else
      perform_action_without_benchmark
    end
  end

  def improved_log_action(payload)
    full_action = "#{params[:controller]}##{params[:action]}"

    message = "#{payload[:remote_ip]} #{payload[:method].to_s.upcase} #{payload[:path]} action=#{full_action}"

    if payload[:format] != :all
      message << " format=#{payload[:format]}"
    end

    if payload[:exception]
      message << " status=#{status_code_for_exception(payload[:exception])}"
    else
      message << " status=#{payload[:status]}"
    end

    if payload[:location]
      message << " location=#{payload[:location]}"
    end

    if payload[:duration]
      message << " duration=#{payload[:duration].to_i}ms"
    end

    if payload[:db_runtime]
      message << " db=#{payload[:db_runtime].to_i}ms"
    end

    if payload[:view_runtime]
      message << " view=#{payload[:view_runtime].to_i}ms"
    end

    if payload[:exception]
      exception_message = payload[:exception].message.to_s
      if exception_message.length > 200
        exception_message = exception_message[0..200] + '...'
      end

      message << %{ exception="#{payload[:exception].class}" exception_message=#{exception_message.inspect}}
    end

    if payload[:change_in_allocated_size]
      message << " allocated_size=#{payload[:change_in_allocated_size]}"
    end

    if payload[:change_in_allocated_objects]
      message << " allocated_objects=#{payload[:change_in_allocated_objects]}"
    end

    unless payload[:params].blank?
      message << " params=#{payload[:params].inspect}"
    end

    logger.info(message)

    if payload[:duration]
      response.headers["X-Runtime"] = "%.0f" % payload[:duration]
    end
  end

  def status_code_for_exception(exception)
    interpret_status(response_code_for_rescue(exception) || DEFAULT_RENDER_STATUS_CODE)[/^([^ ]+)/, 1]
  end
end

class Module
  # Use this to replace a method in an alias_method_chain
  def inject_alias_method_chain(target, method_to_replace, method_to_use)
    method_instance_to_replace = instance_method(method_to_replace)
    meths = (private_instance_methods | instance_methods).sort.grep(/^#{target}/)
    found = meths.detect do |m|
      m != method_to_replace.to_s && instance_method(m) == method_instance_to_replace
    end
    if found
      alias_method found, method_to_use
    end
  end
end

ActionController::Base.class_eval do
  include ImprovedControllerLogging
end

production.log

GET /welcome action=welcome#index format=html status=200 duration=158ms db=0ms view=26ms

production.rb

# Activate improved controller logging
config.after_initialize do
  require 'improved_controller_logging'
end