Custom logger in Rails 2

Posted by bikethetam Wed, 05 Aug 2009 03:19:00 GMT

The default logging format in Rails lacks timestamp and log level, this is how configure logging to the format of your preference.

In Rail 1.2.X, it was enough to just redefine the format_message of the Logger class by just inserting the following lines at the bottom of config/environment.rb:

# custom logging format
class Logger
  private
  def format_message(severity, timestamp, progname, msg)
    "[%5s %s] %s\n" % [severity,
          timestamp.strftime("%m/%d %H:%M:%S"),
          msg]
  end
end

No longer in Rails 2.X as the logger object is now an instance of the ActiveSupport::BufferedLogger class. A bit of monkey patching is needed. Create a new file called custom_logger.rb in the lib directory:

require 'active_support'

# Logger class for custom logging format
class CustomLogger < ActiveSupport::BufferedLogger

  private

    # CustomLogger doesn't define strings for log levels
    # so we have to do it ourselves
    def severity_string(level)
        case level
        when DEBUG
            :DEBUG
        when INFO
            :INFO
        when WARN
            :WARN
        when ERROR
            :ERROR
        when FATAL
            :FATAL
        else
            :UNKNOWN
        end
    end

  public

    # monkey patch the CustomLogger add method so that
    # we can format the log messages the way we want
    def add(severity, message = nil, progname = nil, &block)
        return if @level > severity
        message = (message || (block && block.call) || progname).to_s
        # If a newline is necessary then create a new message ending with a newline.
        # Ensures that the original message is not mutated.
        message = "[%5s %s] %s\n" % [severity_string(severity),
                            Time.now.strftime("%m/%d %H:%M:%S"),
                            message] unless message[-1] == ?\n
        buffer << message
        auto_flush
        message
    end

end

And modify environment.rb the following way:

require File.join(File.dirname(__FILE__), 'boot')
require 'custom_logger'

Rails::Initializer.run do |config|

  ...

  # Force all environments to use the same logger level
  # (by default production uses :info, the others :debug)
  config.log_level = ENV['RAILS_ENV']=='production' ?
                                 ActiveSupport::BufferedLogger::Severity::INFO :
                                 ActiveSupport::BufferedLogger::Severity::DEBUG

  # initializing custom logger
  config.logger = CustomLogger.new(config.log_path, config.log_level)

end

That does 2 things:

  • if running in production mode, no message with a level lower than INFO will be printed
  • the format of every log message will include level, timestamp and message

Example:

[ INFO 08/04 20:34:41]   Session ID: 78e4de86b30d6d704a9f6f44717a4288
[ INFO 08/04 20:34:41]   Parameters: {"action"=>"buy", "controller"=>"article"}

 


Comments

Leave a comment

  1. Seth Thomas Rasmussen 3 months later:

    Handy heads up. Thanks.

  2. Seth Thomas Rasmussen 3 months later:

    Actually, after tinkering and thinking about it more, I'm not sure this is the right approach. I think the removal of message formatting code from the preferred logging class was smart. You are free to wrap and massage your messages before they hit that level of code, and I think that's what I'm going to stick with.. maybe.. ;)

Comments