Rails Logging Tips

  • Posted by Mike Naberezny in Ruby

    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.

    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.

This entry was posted on Saturday, February 24th, 2007 at 6:37 pm and is filed under Ruby.