Move parameters to the top on logging.

actionpack/lib/action_controller/base.rb

@@ -26,6 +26,7 @@ class Base < Metal
     include ActionController::Compatibility
 
     include ActionController::Cookies
+    include ActionController::FilterParameterLogging
     include ActionController::Flash
     include ActionController::Verification
     include ActionController::RequestForgeryProtection
@@ -37,7 +38,6 @@ class Base < Metal
     # Add instrumentations hooks at the bottom, to ensure they instrument
     # all the methods properly.
     include ActionController::Instrumentation
-    include ActionController::FilterParameterLogging
 
     # TODO: Extract into its own module
     # This should be moved together with other normalizing behavior

actionpack/lib/action_controller/metal/filter_parameter_logging.rb

@@ -58,11 +58,6 @@ def filter_parameter_logging(*filter_words, &block)
 
   protected
 
-    def append_info_to_payload(payload)
-      super
-      payload[:params] = filter_parameters(request.params)
-    end
-
     def filter_parameters(params)
       params.dup.except!(*INTERNAL_PARAMS)
     end

actionpack/lib/action_controller/metal/instrumentation.rb

@@ -9,18 +9,24 @@ module ActionController
   module Instrumentation
     extend ActiveSupport::Concern
 
-    included do
-      include AbstractController::Logger
-    end
+    include AbstractController::Logger
+    include ActionController::FilterParameterLogging
 
     attr_internal :view_runtime
 
     def process_action(action, *args)
-      ActiveSupport::Notifications.instrument("action_controller.process_action") do |payload|
+      raw_payload = {
+        :controller => self.class.name,
+        :action     => self.action_name,
+        :params     => filter_parameters(params),
+        :formats    => request.formats.map(&:to_sym)
+      }
+
+      ActiveSupport::Notifications.instrument("action_controller.start_processing", raw_payload.dup)
+
+      ActiveSupport::Notifications.instrument("action_controller.process_action", raw_payload) do |payload|
         result = super
-        payload[:controller]  = self.class.name
-        payload[:action]      = self.action_name
-        payload[:status]      = response.status
+        payload[:status] = response.status
         append_info_to_payload(payload)
         result
       end

actionpack/lib/action_controller/railties/subscriber.rb

 module ActionController
   module Railties
     class Subscriber < Rails::Subscriber
-      def process_action(event)
+      def start_processing(event)
         payload = event.payload
+        info "  Processing by #{payload[:controller]}##{payload[:action]} as #{payload[:formats].first.to_s.upcase}"
         info "  Parameters: #{payload[:params].inspect}" unless payload[:params].blank?
+      end
 
+      def process_action(event)
+        payload   = event.payload
         additions = ActionController::Base.log_process_action(payload)
 
         message = "Completed in %.0fms" % event.duration
         message << " (#{additions.join(" | ")})" unless additions.blank?
-        message << " by #{payload[:controller]}##{payload[:action]} [#{payload[:status]}]"
+        message << " with #{payload[:status]}"
 
         info(message)
       end

actionpack/test/activerecord/controller_runtime_test.rb

@@ -37,8 +37,8 @@ def test_log_with_active_record
     get :show
     wait
 
-    assert_equal 1, @logger.logged(:info).size
-    assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[0]
+    assert_equal 2, @logger.logged(:info).size
+    assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[1]
   end
 
   class SyncSubscriberTest < ActionController::TestCase

actionpack/test/controller/subscriber_test.rb

@@ -63,13 +63,19 @@ def set_logger(logger)
     ActionController::Base.logger = logger
   end
 
+  def test_start_processing
+    get :show
+    wait
+    assert_equal 2, logs.size
+    assert_equal "Processing by Another::SubscribersController#show as HTML", logs.first
+  end
+
   def test_process_action
     get :show
     wait
-    assert_equal 1, logs.size
-    assert_match /Completed/, logs.first
-    assert_match /\[200\]/, logs.first
-    assert_match /Another::SubscribersController#show/, logs.first
+    assert_equal 2, logs.size
+    assert_match /Completed/, logs.last
+    assert_match /with 200/, logs.last
   end
 
   def test_process_action_without_parameters
@@ -82,14 +88,14 @@ def test_process_action_with_parameters
     get :show, :id => '10'
     wait
 
-    assert_equal 2, logs.size
-    assert_equal 'Parameters: {"id"=>"10"}', logs[0]
+    assert_equal 3, logs.size
+    assert_equal 'Parameters: {"id"=>"10"}', logs[1]
   end
 
   def test_process_action_with_view_runtime
     get :show
     wait
-    assert_match /\(Views: [\d\.]+ms\)/, logs[0]
+    assert_match /\(Views: [\d\.]+ms\)/, logs[1]
   end
 
   def test_process_action_with_filter_parameters
@@ -98,7 +104,7 @@ def test_process_action_with_filter_parameters
     get :show, :lifo => 'Pratik', :amount => '420', :step => '1'
     wait
 
-    params = logs[0]
+    params = logs[1]
     assert_match /"amount"=>"\[FILTERED\]"/, params
     assert_match /"lifo"=>"\[FILTERED\]"/, params
     assert_match /"step"=>"1"/, params
@@ -108,34 +114,34 @@ def test_redirect_to
     get :redirector
     wait
 
-    assert_equal 2, logs.size
-    assert_equal "Redirected to http://foo.bar/", logs[0]
+    assert_equal 3, logs.size
+    assert_equal "Redirected to http://foo.bar/", logs[1]
   end
 
   def test_send_data
     get :data_sender
     wait
 
-    assert_equal 2, logs.size
-    assert_match /Sent data omg\.txt/, logs[0]
+    assert_equal 3, logs.size
+    assert_match /Sent data omg\.txt/, logs[1]
   end
 
   def test_send_file
     get :file_sender
     wait
 
-    assert_equal 2, logs.size
-    assert_match /Sent file/, logs[0]
-    assert_match /test\/fixtures\/company\.rb/, logs[0]
+    assert_equal 3, logs.size
+    assert_match /Sent file/, logs[1]
+    assert_match /test\/fixtures\/company\.rb/, logs[1]
   end
 
   def test_send_xfile
     get :xfile_sender
     wait
 
-    assert_equal 2, logs.size
-    assert_match /Sent X\-Sendfile header/, logs[0]
-    assert_match /test\/fixtures\/company\.rb/, logs[0]
+    assert_equal 3, logs.size
+    assert_match /Sent X\-Sendfile header/, logs[1]
+    assert_match /test\/fixtures\/company\.rb/, logs[1]
   end
 
   def test_with_fragment_cache
@@ -143,9 +149,9 @@ def test_with_fragment_cache
     get :with_fragment_cache
     wait
 
-    assert_equal 3, logs.size
-    assert_match /Exist fragment\? views\/foo/, logs[0]
-    assert_match /Write fragment views\/foo/, logs[1]
+    assert_equal 4, logs.size
+    assert_match /Exist fragment\? views\/foo/, logs[1]
+    assert_match /Write fragment views\/foo/, logs[2]
   ensure
     ActionController::Base.perform_caching = true
   end
@@ -155,9 +161,9 @@ def test_with_page_cache
     get :with_page_cache
     wait
 
-    assert_equal 2, logs.size
-    assert_match /Write page/, logs[0]
-    assert_match /\/index\.html/, logs[0]
+    assert_equal 3, logs.size
+    assert_match /Write page/, logs[1]
+    assert_match /\/index\.html/, logs[1]
   ensure
     ActionController::Base.perform_caching = true
   end