“Logging in Ruby on Rails”

Ruby on Rails has a bunch of built in configuration items that are
related to logging. You can set them up in your environment.rb file, or
any of the specific environment override files. Here’s an example of
that file with all of the attributes listed:

Rails::Initializer.run do |config|  config.logger = Logger.new  config.log_level = :debug  config.log_path = "log/myfilename.log"  config.whiny_nils = true  config.active_record.logger = Logger.new  config.active_record.colorize_logging = false  config.action_controller.logger = Logger.new  config.action_mailer.logger = Logger.newend

The logger attributes allow you to create a global
logger, or a specific logger for the active record, action controller
and action mailer framweworks. The log_level controls how much logging gets printed out (we’ll see an example a bit later). log_path defines the location of your log file. whiny_nils gives you some more verbose output if you call a method on a nil object, and colorize_logging gives you colored output in your logs, which is useful if you’re viewing them in a *nix terminal window.

As an example, I can create a Rails controller like this.

class SampleController < ApplicationController  def do_logging    logger.debug("what?")    logger.info("done")    logger.warn("uh oh")    logger.error("bang!")    logger.fatal("KABOOM")  endend

When executing the do_logging method on this class in a newly created Rails application, the following output appears in the terminal window:

what?doneuh ohbang!KABOOM

I don’t find this very useful, so I try configuring my Rails applications wth log4r instead. Here’s an example of my setup in the development.rb file.

config.log_level = :debugLog4r::Logger.root.level = Log4r::DEBUGformatter = Log4r::PatternFormatter.new(:pattern => "[%5l] %d %30C - %m")Log4r::StderrOutputter.new('console', :formatter => formatter)Log4r::Logger.new('App').add('console')RAILS_DEFAULT_LOGGER = Log4r::Logger.new('App::Rails')

This has substituted the Rails logger with a Log4r logger instead. The
pattern formatter has been configured to print out the log level, date,
context (logger name) and a log message. I’ve created a top level
logger call ‘App’, and another logger called ‘Rails’ which is a child
of the ‘App’ logger. The call to Logger.new with the parameter
‘App::Rails’ hooked the two together by name. Log4r loggers write to
their parents output as well as their own, so I don’t need to create
any more outputters. Finally, I set my newly created logger to be the
default Rails logger. Running my controller again now produces this
output:

[DEBUG] 2007-06-26 11:45:56              App::Rails - what?[ INFO] 2007-06-26 11:45:56              App::Rails - done[ WARN] 2007-06-26 11:45:56              App::Rails - uh oh[ERROR] 2007-06-26 11:45:56              App::Rails - bang![FATAL] 2007-06-26 11:45:56              App::Rails - KABOOM

That’s much more useful now, however, I don’t have any meaningful
way of distinguishing log messages coming from the Rails framework to
log messages coming from my code. Framework log messages will all have
the context of ‘App::Rails’ too. I’d like to have a different context.
I can now change my controller to be like this though.

require "log4r"

class SampleController < ApplicationController  def initialize    @@log = Log4r::Logger.new('App::SampleController')  end

  def do_logging    @@log.debug("what?")    @@log.info("done")    @@log.warn("uh oh")    @@log.error("bang!")    @@log.fatal("KABOOM")  endend

Making this change gets me the following output:

[DEBUG] 2007-06-26 11:45:56   App::SampleController - what?[ INFO] 2007-06-26 11:45:56   App::SampleController - done[ WARN] 2007-06-26 11:45:56   App::SampleController - uh oh[ERROR] 2007-06-26 11:45:56   App::SampleController - bang![FATAL] 2007-06-26 11:45:56   App::SampleController - KABOOM

Now I can easily tell apart my log messages from the Rails framework messages.

You may have noticed that the Log4r configuration I used in
development mode only outputs to the console, and not to a file as
happens by default. I find that much more useful, as I don’t have to
bother cleaning up development log files any more. One final Log4r
trick that I use is in production mode is to use a different outputter
that automatically creates a new log file every day and names the files
according to date. My production.rb file looks like this:

config.log_level = :warnLog4r::Logger.root.level = Log4r::WARNformatter = Log4r::PatternFormatter.new(:pattern => "[%5l] %d %30C - %m")Log4r::DateFileOutputter.new('logfile', :dirname => "log", :formatter => formatter)Log4r::Logger.new('App').add('logfile')RAILS_DEFAULT_LOGGER = Log4r::Logger.new('App::Rails')

Those settings makes it easy to manage log files in production mode.
Some people have reported possible errors when multiple mongrel
processes try to roll a log file at the same time, and I haven’t tested
it in anger. Be careful that you test if you get into that situation.
Otherwise, this setup has worked quite well for me.

Powered by ScribeFire.