This post originated from an RSS feed registered with Agile Buzz by Marty Andrews. Original Post: Logging in Ruby on Rails Feed Title: Ramblings of the Wry Tradesman Feed URL: http://www.wrytradesman.com/blog/index.rdf Feed Description: Marty Andrews talks about the day to day issues he faces as an agile coach on large enterprise applications in Australia. Latest Agile Buzz Posts Latest Agile Buzz Posts by Marty Andrews Latest Posts From Ramblings of the Wry Tradesman

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.new
end

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")
  end
end

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

what?
done
uh oh
bang!
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 = :debug
Log4r::Logger.root.level = Log4r::DEBUG
formatter = 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")
  end
end

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 = :warn
Log4r::Logger.root.level = Log4r::WARN
formatter = 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.