Recipe 10.4. Logging with the Built-in Rails Logger Class

Problem

Contributed by: Bill Froelich

You want your application to send certain messages to logfiles. You want to assign different severities to these messages; some may represent serious system problems, while others may just be informative. You want to handle these log messages differently in your production and development environments.

Solution

Use the built-in logging methods to differentiate your messages and allow you to control the level of logging.

Rails automatically creates a logfile specific to the environment settings and makes it accessible to your Rails application. To send messages to the log, simply include the appropriate calls in your models, controllers, and views. For example:

logger.debug "My debug message"

This call to Logger.debug writes the message "My debug message" to the #{RAILS_ROOT}/log/development.log file.

The built-in logger supports five severity levels in increasing priority (debug, info, warn, error, fatal) that can be used to differentiate your messages:

logger.debug "My debug message - lowest priority" logger.info "Informational message" logger.warn "Something unexpected happened" logger.error "An error occurred during processing" logger.fatal "A fatal error occurred accessing the database"

You can set which types of messages get logged by changing the log_level in environment.rb:

config/environment.rb:

Rails::Initializer.run do |config|    config.log_level = :debug end

This configuration setting causes all messages with a severity equal to or greater than the specified severity (debug, in this case) to be written to the logfile. Because debug is the lowest severity, all messages are sent to the logfile.

Discussion

The built in Logger class provides a convenient interface for logging all messages from your Rails application. Using it requires you to add logger calls with an appropriate severity throughout your application. The severity level allows you to keep detailed log messages during debugging, then suppress most of the messages when the application is in production by changing the log_level.

The logger also provides methods to check if the current logger responds to certain messages:

logger.debug? logger.info? logger.warn? logger.error? logger.fatal?

Each of the methods returns true if the current severity level outputs messages on that level. You can use these methods to wrap a block of code whose only purpose is generating values for output at a specific severity level.

if logger.debug? then   # Code to calculate logging values ...   logger.debug "Debug Message" + Calculated_values end

By wrapping the code with the conditional, logger.debug executes only if debug messages are enabled for the environment in which this code is run.

By default, the built-in logger just outputs the message as provided to the logfile. While this works, it doesn't provide information about the severity of the messages being logged or the time the message was written to the log. Fortunately, this can be modified by overriding the format_message method in the Logger class.

config/environment.rb:

class Logger   def format_message(severity, timestamp, progname, msg)     "[#{timestamp.strftime("%Y-%m-%d %H:%M:%S")}] #{severity}  #{msg}\n"   end end

This change causes all messages to be written to the log with the date and time, followed by the severity and then the message:

Processing LogTestingController#index (for 127.0.0.1 at 2006-06-08 21:47:06) [GET] [2006-06-08 21:47:06] INFO    Session ID: 8c798c964837cab2372e51b478478865 [2006-06-08 21:47:06] INFO    Parameters: {"action"=>"index", "controller"=>"log_testing"} [2006-06-08 21:47:06] DEBUG  your message here... [2006-06-08 21:47:06] INFO  Rendering log_testing/index [2006-06-08 21:47:06] INFO  Completed in 0.01071 (93 reqs/sec) | Rendering: 0.00384 (35%)  | 200 OK [http://localhost/log_testing

Having the ability to log messages allows you to capture run-time information about your application. Sometimes finding what you are looking for in the logfile can be difficult because your messages are mixed with messages from the Rails framework itself. This is especially true in development mode when the framework is logging liberally. To separate your log messages from Rails' messages, write your logging messages to your own logfile. Start by configuring your own logger, with its own logfile:

config/environment.rb:

APPLOG = Logger.new("#{RAILS_ROOT}/log/my-app.log") APPLOG.level = Logger::DEBUG

Once you have your logfile created, simply use it in your models, controllers, and views to log your messages:

app/controllers/recipe_controller.rb:

class RecipeController < ApplicationController   def list     APPLOG.info("Starting Recipe List Method")     @category = params['category']     @recipes = Recipe.find_all     APPLOG.debug(@recipes.inspect)     APPLOG.info("Leaving Recipe List Method")   end end

You can also call these methods within your views:

app/views/recipe/list.rhtml:

<% APPLOG.debug "Log message from a view" %>

Your new logger object responds to the same set of methods and uses the same message format as the built-in logger.

See Also

• Section 4.10"