rails/rails — pull request #3929 by schneems (2011-12-10 17:02:46+00:00)
Title: Add Callback Logging to ActiveSupport and Apply Filter logging to AbstractController 

# What

Adding the ability to easily log callbacks and controller [before/around/after]_filters.

# Why

One of the biggest problems students in my [rails classes](http://schneems.com/beginner-to-builder-2011) 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

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

```

## Before Logging

```shell
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

```shell
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

```ruby
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
```

```shell
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)
```

## Feedback

I've opened this discussion prior on a gist: https://gist.github.com/1443757 and on the Austin twitter channels and gotten positive feedback. I'm happy to talk about this in IRC or on a list or in this pull request.