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.

See Also

"