Dealing with Errors in Rails

Jeff Atwood's recent blog post on "Exception-Driven Development" has driven me to write a post that I've been thinking about writing for the last couple weeks.

I'm working on a Rails application in my spare time, and one of the concepts I wanted to drill into the codebase from the beginning was easy management of the system from within the system. This means I can log in and, given that I have the proper access, view errors that have happened in the site, migrate the database, restart the application, and perform various other actions that would otherwise require tedious activities like digging in log files, or obtaining shell access and executing various commands. While I am quite comfortable on the shell (I run Linux on all the machines that I use with any regularity), I would much rather have an easy to use GUI that gives me access in the context of when I need it (ie, when I am actually checking up on the website... from within it).

So, this post will basically show you how to add error logging within your Rails application, as I've done in mine.

First up: the database. Here's the database migration script you will need:

class CreateErrors < ActiveRecord::Migration
 def self.up
   create_table :errors do |t|
     t.string :level
     t.string :title
     t.boolean :handled
     t.text :description

     t.timestamps
   end
 end

 def self.down
   drop_table :errors
 end
end

The level column is so you can keep track of errors vs warnings, or have informational messages as well. It's not strictly necessary, but I want the flexibility, plus I'm used to the concept from all the logging frameworks that support multiple levels of messages.

The title and description should be self explanatory. In case you are slow though, the title is just a header so you can at a glance see what errors have cropped up, and the description provides a detailed look at the error (such as a backtrace).

The handled column is critical so you can keep track of which errors you have dealt with, and which need looking at. It acts as a soft delete.

Since you've seen the database end, you might as well peak at the model next:

class Error < ActiveRecord::Base
  def self.error(title, description)
    log :error, title, description
  end

  def self.warn(title, description)
    log :warn, title, description
  end

  def self.info(title, description)
    log :info, title, description
  end

  def self.log(level, title, description)
    Error.new(:level => level.to_s, :title => title,
        :description => description, :handled => false).save
  end
end

The error, warn and info methods are to easily log something at the given level, much like a typical logging library. All of those methods use the one logging method which will actually save the error as a row in the database. Pretty simple, as is the usual case with ActiveRecord classes! You could make a case for making the log method private, but I don't really want to, so I won't.

Next up, the errors controller:

class ErrorsController < ApplicationController
  title "Errors"
  require_admin

  def index
    @total = Error.count :all, :conditions => ["handled = ?", false]
    @errors = Error.find :all,
        :conditions => ["handled = ?", false],
        :order => "created_at DESC", :limit => 50
    @start = [1, @total].min
    @amount = @errors.size
  end

  def show
    @error = Error.find params[:id]
  end

  def handle
    @error = Error.find params[:id]
    @error.update_attributes :handled => true
    redirect_to errors_url
  end
end

The title and require_admin methods are some utility methods I baked into the base controller... I may publish those at some point, but they aren't the focus of this post, so not now. If I get any comments requesting the code, I will probably follow up with the code, so let me know if it is intriguing you! Their purpose are to set the title on all views associated with this controller, and check for administrator privileges respectively.

If you will notice, the index will only load the most recent 50 errors... I figured it would be possible for the application to get in a weird loop where you trigger tons and tons of errors. I wouldn't want to haplessly check out the current list of errors, only to watch in horror as I am downloading a list of 100,000 errors. The handle method is the only means to update an error... and it simple turns on the soft delete so the error won't show anymore. It might make sense to set up a mass handled action which would handle a group of selected errors all at once... but I don't really need that yet... I will build it when the need arises.

The rest in index should make sense as you check out the index.html.erb view:

<h1>Listing errors</h1>

<p>
  <%= @start %> - <%= @amount %> of <%= @total %> errors.
</p>

<table>
  <tr>
    <th>Date</th>
    <th>Level</th>
    <th>Title</th>
  </tr>

<% @errors.each do |error| %>
  <tr>
    <td><%= h format_datetime(error.created_at) %></td>
    <td><%= h error.level %></td>
    <td><%= h truncate(error.title, :length => 100) %></td>
    <td><%= h error.handled %></td>
    <td><%= link_to "Show", error %></td>
    <td><a href="/errors/handle/<%= error.id %>">Handled</a></td>
  </tr>
<% end %>
</table>

Pretty straightforward, huh? Well, here's show.html.erb

<p>
  <b>Title:</b>
  <%= h @error.title %>
</p>

<p>
  <b>Time:</b>
  <%= h format_datetime(@error.created_at) %>
</p>

<p>
  <b>Level:</b>
  <%= h @error.level %>
</p>

<p>
  <b>Description:</b>

  <br/>

  <%= format_multilines h(@error.description) %>
</p>

<a href="/errors">Back</a>

Also pretty simple. If you are curious about format_datetime and format_multilines, they are simple helpers I created to respectively format a date as I want them formatted, and take a string with newlines and convert the newlines to <br/> elements. Pretty simple helpers, but I like keeping as much logic off my views as possible.

That's it! Or wait... that's all the stuff that rails practically generates for you (tweaked for simplicity, but still). How can this stuff get put into practice? Well, I'll give you that code too... since you've gotten this far. In your base application controller:

class ApplicationController < ActionController::Base
  RENDER_LIMIT = 0.5
  around_filter :time_page

...

  private
  def time_page
    before = Time.new
    yield
    after = Time.new
    delta = after - before

    if delta >= RENDER_LIMIT
      title = "Page took #{delta} seconds to render"
      description = "Execution of #{request.path} took #{delta} seconds to render."
      Error.warn title, description
    end
  end

  def rescue_action(e)
    title = "Caught exception '#{e}'"
    description = "Exception was caught: '#{e}'\n\nBacktrace:\n#{e.backtrace.join("\n")}"
    Error.error title, description
    super
  end
end

With this addition, your new in-site error reporting mechanism will report any page that takes over half a second to load, or absolutely any exception that crops up. This includes failing to parse a Ruby file, actions or controllers that were browsed to that don't exist, or any random exception the user encounters. You may want to adjust the RENDER_LIMIT constant to the threshold of your liking. At some point I would like to add a separate timer for all database queries, but I haven't had the time or interest to do it yet... and besides, the render limit should encompass all queries anyways, so it would be slightly redundant (though I would like to have a much lower threshold of query time than render time).

And as a caveat, this will not report a failure to parse the application controller Ruby file... because... well... think about it and you should realize why it can't :-)

Go forth and practice Exception-Driven Development in Rails.