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
Adding the ability to easily log callbacks.
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!
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.
class PostsController < ApplicationController
before_filter :check_admin
# ...
end
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)
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