Logging HTTP Error Messages in Ruby and Rails

Rails comes with some default logging stuff built in, but if you’re used to the sophistication of the log4x frameworks, it’s pretty basic.

One of my requirements is to be able to log exceptions that occur during an ActionController HTTP request, and have the configurable logging mechanism decide what to do with them – most likely send emails and write to syslog in production, in development I’ll want it to write to a file and maybe growl.

Looking around the web, there was a project to port log4j to Ruby, but it appears to be moribund. The imaginatively named Logging framework looks a lot more lively and mature. I mean, it’s on github… What more could a budding Ruby hipster possibly want?

The logging Pipeline

Once you’ve seen a logging framework, you’ve seen them all. Logging helpfully uses familiar terminology from the log4x domain, which helps us pick things up. Let’s take a tour through the life of a log message to review the domain.

The first thing you need is an instance of Logging::Logger. Conventionally, you create a logger per instrumented class. Logger uses a Repository to create / retrieve loggers, so you get hold of your logger like this:

class MyClass
  def initialize
    @logger = Logging::Logger[self]
  end
end

When your Logger is created, the Logger class creates instance methods through which you can log events. By default these are #debug, #info, #warn, #error and #fatal. These are nice defaults to use in a Rails app, as they slot right into the interface Rails is expecting from its logger.

Each of these methods can be called in two ways, passing a piece of data either as a parameter or as a block:

@logger.warn "something bad happened"

@logger.debug do
  "we have seen #{WidgetMonger.calculate} widgets today"
end

The second technique is useful if you’re doing something expensive as you create the message – the block will only be called after the logger has checked whether, at its current logging level, it’s interested in what you have to say.

This data is then rolled up along with some other useful details into a Logger::LogEvent object, and passed out to each of the Logger’s registered Appenders (it’s also passed up to the Logger’s parent, if it has one, but that’s another story).

When the LogEvent reaches an Appender, it’s passed to the Appender#write method. The Appender is then expected to pass the event out to the Layout object it was given when it was constructed by the Logger, calling Layout#format to get a string representation of the LogEvent. The Appender then sends this string to its given output channel, be it an email, a growl, or a plain old textfile.

Back to the HTTP Logging Problem

So… here we are in the ActionController, there’s been an error. Here’s a naive way to log it:

class ApplicationController < ActionController::Base
  def logger
    Logging::Logger[self]
  end
  # Override rails default method
  def log_error(exception)
    logger.error(exception)
  end  
end

In fact, we could just override the logger method, and ActionController::Base would be calling our logger rather than its own, but the base class implementation of log_error uses uses the :fatal level, and I think that’s a little bit dramatic for an error in this one request. I’m wounded, sure, but I think I’ll make it through.

Trouble is, when this logged event finally gets in front of a human, they get none of the detail we’d expect from something like the ExceptionNotifier plugin. We want HTTP headers, we want session variables. So we need to pass some more detail into the logging machine. What’s the best way to do that?

Well, it turns out that the base Layout class takes a :format_as option in its constructor, which we can use to format the original logged object as yaml. We’ll use this as our first pass to produce a readable, useful error message from our application.

def log_error(exception)
  logger.error(
    :exception => exception,
    :session => request.session,
    :parameters => request.parameters,
    :environment => request.env)
end  

Let’s hook all this up. Create the following module in your lib directory:

module Diagnostics
  class << self
    def init
      Logging.init

      # see http://logging.rubyforge.org/classes/Logging/Layouts/Pattern.html
      detailed_layout     = Logging::Layouts::Pattern.new(:pattern => <<-FORMAT, :format_as => :yaml)
----
  Level:      %-5l
  Date:       %d
  Logger:     %c
  Process ID: %p
  Thread ID:  %t
  Message:
  %m
FORMAT

      root = Logging::Logger[:root]
      root.appenders = \
        Logging::Appenders::RollingFile.new(
          'log/development-errors.log',
          :layout => detailed_layout,
          :level  => :error )

      root.level = :debug
    end
  end
end

Then add a call to Diagnostics.init to your environment.rb, or somewhere like that.

Finally create a controller that deliberately throws exceptions:

class ExceptionsController < ApplicationController
  def create
    raise Exception.new("Boom!")
  end
end

Now from script/console, you can drive the whole thing:

>>app.post '/exceptions'

You should see an entry in your development-errors logfile.

Hopefully this gives you enough to get you up and runnning with your own logging. My plan is to replace our use of the exception notifier plugin with a clean system using the Logging framework only. Please feel free to post your feedback, or your own configuration settings.