Move parameters to the top on logging.

4 files changed, 20 insertions, 15 deletions

diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb
index 260e5da336..f86a61d791 100644
--- a/actionpack/lib/action_controller/base.rb
+++ b/actionpack/lib/action_controller/base.rb
@@ -26,6 +26,7 @@ module ActionController
     include ActionController::Compatibility
 
     include ActionController::Cookies
+    include ActionController::FilterParameterLogging
     include ActionController::Flash
     include ActionController::Verification
     include ActionController::RequestForgeryProtection
@@ -37,7 +38,6 @@ module ActionController
     # 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
diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
index 0b1e1ee6ab..9e03f50759 100644
--- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
+++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
@@ -58,11 +58,6 @@ module ActionController
 
   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
diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb
index 876f778751..7b2b037c67 100644
--- a/actionpack/lib/action_controller/metal/instrumentation.rb
+++ b/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
diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb
index 6659e5df47..d257d6ac2c 100644
--- a/actionpack/lib/action_controller/railties/subscriber.rb
+++ b/actionpack/lib/action_controller/railties/subscriber.rb
@@ -1,15 +1,19 @@
 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