Marty Andrews

artful code

Sunday, September 2, 2007

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: do |config|config.logger = Logger.newconfig.log_level = :debugconfig.log_path = "log/myfilename.log"config.whiny_nils = trueconfig.active_record.logger = Logger.newconfig.active_record.colorize_logging = falseconfig.action_controller.logger = Logger.newconfig.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 < ApplicationControllerdef do_logginglogger.debug("what?")"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 = => "[%5l] %d %30C - %m")'console', :formatter => formatter)'App').add('console')RAILS_DEFAULT_LOGGER ='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 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 < ApplicationControllerdef initialize@@log ='App::SampleController')enddef do_logging@@log.debug("what?")"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 = => "[%5l] %d %30C - %m")'logfile', :dirname => "log", :formatter => formatter)'App').add('logfile')RAILS_DEFAULT_LOGGER ='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.