Rails Logging Tips

Ruby on Rails comes prewired for logging using Logger from the Ruby Standard Library. This article demonstrates how to use the Rails logger, how to create your own logs, and offers some tips for debugging with console logging.

In this article, we'll take a look at how to use the logging facilities built into Rails and then share a few tips:

Accessing the Rails Logger

Rails automatically sets up logging to a file in the log/ directory using Logger from the Ruby Standard Library. Do not confuse this with Log4r, a completely different library. The logfile will be named corresponding to your environment, e.g. log/development.log.

To log a message from either a controller or a model, access the Rails logger instance with the logger method: 

class HomeController < ActionController::Base
  def index
    logger.info 'informational message'
  end
end

From outside a controller or model, you can pass the logger instance or access it with the constant RAILS_DEFAULT_LOGGER.

Log Levels

In the snippet above, a message is logged at the INFO level by calling a method of the same name (info).

The levels available on the logger are (in ascending order): debug, info, warn, error, and fatal.

Ruby's Logger supports masking levels so the types of messages recorded in the log can be controlled. By default, Rails will log all levels (debug and higher) in every environment except production. In the production environment, it will only log info and higher. This behavior can be changed in the configuration for each environment.

Reducing Log File Size

As noted above, the production environment logs at the info level and higher by default. This means that for every request received, messages will be written to the log about the request.

As your traffic increases, the amount of log data can become overwhelming and in some cases, writing the log to disk will begin to impact your server performance.

You can choose to log only at the warn level and higher. To do this, add a line to your environments/production.rb: 

config.log_level = :warn

Your log file size will be significantly reduced, with the tradeoff being less visibility into your application server's operation.

A common cause of log bloat is the exception traces written to the log when clients make requests that result in 404 Not Found. Humans and robots alike will request all kinds of bogus things, so this happens often. Add this snippet to your ApplicationController: 

EXCEPTIONS_NOT_LOGGED = ['ActionController::UnknownAction',
                         'ActionController::RoutingError']

protected
  def log_error(exc)
    super unless EXCEPTIONS_NOT_LOGGED.include?(exc.class.name)
  end

With the snippet above installed, UnknownAction and RoutingError errors will not be logged but all others will.

Filtering Sensitive Parameters

When Rails receives a request, ActionController logs the request parameters. This is very handy for debugging but sometimes it's not desirable to have certain parameters, such as passwords, stored as plain text in the log.

Rails 1.2 introduced the filter_parameter_logging class method to remedy this: 

class ApplicationController < ActionController::Base
  filter_parameter_logging :password
end

The above will cause any parameter name matching /password/i to have its value replaced with [FILTERED] in the log. To filter multiple parameters, simply add them as extra arguments to filter_parameter_logging by separating them with commas. For other uses of filter_parameter_logging, see the ActionController documentation.

Note: it's important to remember that filter_parameter_logging will only filter ActionController request information. The parameters could still appear in any SQL queries being logged by ActiveRecord. However, SQL queries are not logged in the production environment by default.

Creating Audit Logs

Sometimes logging is required but putting the messages in the Rails log isn't desirable. One such case is when keeping a separate logfile for auditing is a business requirement.

To create an audit log, simply create a new instance of Logger and pass it a File instance for your own logfile.

One possible source of confusion is the formatting of the log message due to a patch Rails makes to Logger. This can be seen when using irb as opposed to script/console: 

$ irb
irb(main):001:0> require 'logger'
=> true
irb(main):002:0> Logger.new(STDOUT).info('message')
I, [2007-02-24T09:45:51.236763 #557]  INFO -- : message


$ script/console
Loading development environment.
>> Logger.new(STDOUT).info('message')
message

As you can see, the message formatting is lost when run in the Rails environment. To format a log message when using Rails, create your own Logger subclass and implement the format_message method: 

class AuditLogger < Logger
  def format_message(severity, timestamp, progname, msg)
    "#{timestamp.to_formatted_s(:db)} #{severity} #{msg}\n" 
  end 
end

To use the new AuditLogger, instantiate it with a File instance: 

logfile = File.open('/path/to/audit.log', 'a')    
audit_log = AuditLogger.new(logfile)

Your new log is now ready to use by calling methods on it like audit_log.info 'message'.

One important point to remember is that the logfile object does not implicitly flush to the file by default. This means that your code must call logfile.flush for the data to be written out. Alternatively, you can set logfile.sync = true to turn on implicit flushing.

ActiveRecord Logging on the Console

When debugging your applications with script/console, it can be very useful to see the SQL output of your ActiveRecord queries. One way to do this is to use tail -f on your logfile.

However, this isn't very convenient and shows all other log information as well. An easier way that can be done directly from script/console is to enter this line: 

ActiveRecord::Base.logger = Logger.new(STDOUT)

This will cause the queries to be displayed immediately on the console as you interact with your ActiveRecord objects with method calls like Article.find :all.

ActionController Logging on the Console

Just like with ActiveRecord above, you can also redirect ActionController's log output to the console when using script/console: 

ActionController::Base.logger = Logger.new(STDOUT)

You can then observe ActionController activities when using using using the app object on the console, such as app.get '/'. For a brief tutorial on using app, see this post on Mike Clark's weblog.

Firebug Console

Firebug is a popular extension for the Firefox browser that provides a number of useful capabilities, with a Javascript console being among them. The console is accessed by console.log('message') in Javascript.

This means that any Rails view emitting this little Javascript call between <script> tags can write to the Firebug console.

It also means that any RJS template can write to the Firebug console for debugging: 

page.call 'console.log', 'informational message'

This can be very useful for logging debug information during AJAX requests where a popup from alert() isn't desirable.