[Rails Cookbook Recipe 4.9] Inspecting Requests with Filters

Recipe 4.9. Inspecting Requests with Filters
Problem
You have taken over development of a Rails application, and you are trying to figure out how it processes requests. To do so, you want to install a logging mechanism that will let you inspect the request cycle in real time.

Solution
Use an after_filter to invoke a custom logging method for each request. Define a CustomLoggerFilter class:

app/controllers/custom_logger_filter.rb:

require 'logger'
require 'pp'
require 'stringio'

class CustomLoggerFilter

def self.filter(controller)
log = Logger.new('/var/log/custom.log')
log.warn("params: "+controller.params.print_pretty)
end
end

class Object
def print_pretty
str = StringIO.new
PP.pp(self,str)
return str.string.chop
end
end

Install the logger in the AccountsController by passing it as an argument in a call to after_filter:

app/controllers/accounts_controller.rb:

class AccountsController < ApplicationController

after_filter CustomLoggerFilter

def index
list
render :action => 'list'
end

def list
@account_pages, @accounts = paginate :accounts, :per_page => 10
end

def show
@account = Account.find(params[:id])
end

def new
@account = Account.new
end

def create
@account = Account.new(params[:account])
if @account.save
flash[:notice] = 'Account was successfully created.'
redirect_to :action => 'list'
else
render :action => 'new'
end
end

def edit
@account = Account.find(params[:id])
end

def update
@account = Account.find(params[:id])
if @account.update_attributes(params[:account])
flash[:notice] = 'Account was successfully updated.'
redirect_to :action => 'show', :id => @account
else
render :action => 'edit'
end
end

def destroy
Account.find(params[:id]).destroy
redirect_to :action => 'list'
end
end

Discussion
Rails filters allow you to do additional processing before or after controller actions. In the solution, we've implemented a custom logging class that is invoked after calls to any actions in the Accounts controller. Our logger opens a filehandle and prints a formatted version of the params hash for easy inspection.

With the logger in place, you can use the Unix tail command to watch the logfile as it grows. You'll see what happens to the params hash with every action that's called:

tail -f /var/log/custom.log

For the AccountsController in the solution, you can watch the log as you list, create, and destroy accounts.

params: {"action"=>"list", "controller"=>"accounts"}
params: {"action"=>"new", "controller"=>"accounts"}
params: {"commit"=>"Create",
"account"=>{"balance"=>"100.0", "first_name"=>"John", "last_name"=>"Smythe"},
"action"=>"create",
"controller"=>"accounts"}
params: {"action"=>"list", "controller"=>"accounts"}
params: {"action"=>"destroy", "id"=>"2", "controller"=>"accounts"}
params: {"action"=>"list", "controller"=>"accounts"}

Rails comes with a number of built-in logging facilities. This approach gives you an easy way to add logging to a controller with only one line of code. You can also limit what actions of the controller the filter is applied to.