Add Callback Logging to ActiveSupport and Apply Filter logging to AbstractController

gistfile1.md

This is a patch i'm interested in submitting to rails https://github.com/schneems/rails/commits/schneems/log_controller_filters/ (last two commits) but first I want some feedback. Here is a writeup similar to how I would structure a PR. All comments welcome, especially alternative implementation & style, here it goes...

UPDATE: Pull request submitted, please post any comments there: rails/rails#3929

What

Adding the ability to easily log callbacks.

Why

One of the biggest problems students in my rails classes face, is tracking down an errant redirect or other misbehaving code. Even after working with rails for many years it can be difficult to navigate the filter chain in a large application. By giving the filters more visibility in the logs we speed up debugging and everyone wins!

How

Insert an empty function #log_callback on instances of classes that extend ActiveSupport that takes the callback name (function name) and callback type as arguments. Each class can choose how they would like to over-ride this function making logging flexible and easy.

We then define a default implementation of #log_callback in AbstractController::Callbacks to provide us with [before/around/after]_logging in rails.

Result

class PostsController < ApplicationController
  before_filter :check_admin
  # ...
end

Before Logging

Started GET "/posts" for 127.0.0.1 at Wed Dec 07 11:42:44 -0600 2011
  Processing by PostsController#index as HTML
  Post Load (0.1ms)  SELECT "posts".* FROM "posts" 
Rendered posts/index.html.erb within layouts/application (0.4ms)
Completed 200 OK in 11ms (Views: 9.4ms | ActiveRecord: 0.5ms)

After Logging

Started GET "/posts" for 127.0.0.1 at Wed Dec 07 11:44:16 -0600 2011
  Processing by PostsController#index as HTML
    Calling before_filter: verify_authenticity_token
    Calling before_filter: check_admin
  Post Load (0.2ms)  SELECT "posts".* FROM "posts" 
Rendered posts/index.html.erb within layouts/application (2.2ms)
Completed 200 OK in 31ms (Views: 29.5ms | ActiveRecord: 0.2ms)

The callback will not be logged if a callback has not been executed. This means when a callback is specified using:if => lambda {false}, :unless => lambda {true}, or using skip_before_filter it will not appear in the logs.

This is what the output looks like when multiple before/around/after callbacks are specified

class PostsController < ApplicationController
  before_filter :before_foo_1, :before_foo_2
  after_filter  :after_foo_1,  :after_foo_2
  around_filter :around_foo_1, :around_foo_2
  #...
end

Started GET "/posts" for 127.0.0.1 at Wed Dec 07 11:51:41 -0600 2011
  Processing by PostsController#index as HTML
    Calling before_filter: verify_authenticity_token
    Calling before_filter: before_foo_1
    Calling before_filter: before_foo_2
    Calling around_filter: around_foo_1
    Calling around_filter: around_foo_2
  Post Load (0.2ms)  SELECT "posts".* FROM "posts" 
Rendered posts/index.html.erb within layouts/application (3.0ms)
    Calling after_filter: after_foo_2
    Calling after_filter: after_foo_1
Completed 200 OK in 36ms (Views: 34.4ms | ActiveRecord: 0.2ms)

+1