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.

See Also

Section 4.10"