Log 'Filter chain halted as CALLBACKNAME rendered or redirected' every time a before callback halts.

actionpack/CHANGELOG.md

@@ -1,5 +1,7 @@
 ## Rails 3.2.0 (unreleased) ##
 
+*   Log "Filter chain halted as CALLBACKNAME rendered or redirected" every time a before callback halts. *José Valim*
+
 *   You can provide a namespace for your form to ensure uniqueness of id attributes on form elements.
     The namespace attribute will be prefixed with underscore on the generate HTML id. *Vasiliy Ermolovich*
 

actionpack/lib/action_controller/log_subscriber.rb

@@ -29,6 +29,10 @@ module ActionController
       info(message)
     end
 
+    def halted_callback(event)
+      info "Filter chain halted as #{event.payload[:filter]} rendered or redirected"
+    end
+
     def send_file(event)
       message = "Sent file %s"
       message << " (%.1fms)"

actionpack/lib/action_controller/metal/instrumentation.rb

@@ -64,7 +64,12 @@ module ActionController
       end
     end
 
-  protected
+  private
+
+    # A hook invoked everytime a before callback is halted.
+    def halted_callback_hook(filter)
+      ActiveSupport::Notifications.instrument("halted_callback.action_controller", :filter => filter)
+    end
 
     # A hook which allows you to clean up any time taken into account in
     # views wrongly, like database querying time.

actionpack/test/controller/log_subscriber_test.rb

@@ -13,6 +13,11 @@ module Another
       head :status => 406
     end
 
+    before_filter :redirector, :only => :never_executed
+
+    def never_executed
+    end
+
     def show
       render :nothing => true
     end
@@ -49,7 +54,6 @@ module Another
     def with_rescued_exception
       raise SpecialException
     end
-
   end
 end
 
@@ -86,6 +90,13 @@ class ACLogSubscriberTest < ActionController::TestCase
     assert_equal "Processing by Another::LogSubscribersController#show as HTML", logs.first
   end
 
+  def test_halted_callback
+    get :never_executed
+    wait
+    assert_equal 4, logs.size
+    assert_equal "Filter chain halted as :redirector rendered or redirected", logs.third
+  end
+
   def test_process_action
     get :show
     wait

activemodel/lib/active_model/callbacks.rb

@@ -93,7 +93,7 @@ module ActiveModel
          :only => [:before, :around, :after]
       }.merge(options)
 
-      types   = Array.wrap(options.delete(:only))
+      types = Array.wrap(options.delete(:only))
 
       callbacks.each do |callback|
         define_callbacks(callback, options)

activesupport/lib/active_support/callbacks.rb

@@ -81,6 +81,14 @@ module ActiveSupport
       send("_run_#{kind}_callbacks", *args, &block)
     end
 
+    private
+
+    # A hook invoked everytime a before callback is halted.
+    # This can be overriden in AS::Callback implementors in order
+    # to provide better debugging/logging.
+    def halted_callback_hook(filter)
+    end
+
     class Callback #:nodoc:#
       @@_callback_sequence = 0
 
@@ -173,12 +181,14 @@ module ActiveSupport
           # end
           <<-RUBY_EVAL
             if !halted && #{@compiled_options}
-              # This double assignment is to prevent warnings in 1.9.3.  I would
-              # remove the `result` variable, but apparently some other
-              # generated code is depending on this variable being set sometimes
-              # and sometimes not.
+              # This double assignment is to prevent warnings in 1.9.3 as
+              # the `result` variable is not always used except if the
+              # terminator code refers to it.
               result = result = #{@filter}
               halted = (#{chain.config[:terminator]})
+              if halted
+                halted_callback_hook(#{@raw_filter.inspect.inspect})
+              end
             end
           RUBY_EVAL
         when :around

activesupport/test/callbacks_test.rb

@@ -461,7 +461,7 @@ module CallbacksTest
     set_callback :save, :after, :third
 
 
-    attr_reader :history, :saved
+    attr_reader :history, :saved, :halted
     def initialize
       @history = []
     end
@@ -490,6 +490,10 @@ module CallbacksTest
         @saved = true
       end
     end
+
+    def halted_callback_hook(filter)
+      @halted = filter
+    end
   end
 
   class CallbackObject
@@ -595,6 +599,12 @@ module CallbacksTest
       assert_equal ["first", "second", "third", "second", "first"], terminator.history
     end
 
+    def test_termination_invokes_hook
+      terminator = CallbackTerminator.new
+      terminator.save
+      assert_equal ":second", terminator.halted
+    end
+
     def test_block_never_called_if_terminated
       obj = CallbackTerminator.new
       obj.save