Remove ActionView inline logging to ActiveSupport::Notifications and create ActionController::Base#log_event, so everything can be logged within one listener. Also expose log_process_action as a hook for different modules to include their own information during the action processing. This allow ActiveRecord to hook and any other ORM. Finally, this commit changes 'Processing' and 'Rendering' in logs to 'Processed' and 'Rendered' because at the point it's logged, everying already happened.

10 files changed, 108 insertions, 139 deletions

diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb
index e3bcd28da7..a23a13e1d6 100644
--- a/actionpack/lib/abstract_controller/logger.rb
+++ b/actionpack/lib/abstract_controller/logger.rb
@@ -9,25 +9,5 @@ module AbstractController
       cattr_accessor :logger
       extend ActiveSupport::Benchmarkable
     end
-
-    # A class that allows you to defer expensive processing
-    # until the logger actually tries to log. Otherwise, you are
-    # forced to do the processing in advance, and send the
-    # entire processed String to the logger, which might
-    # just discard the String if the log level is too low.
-    #
-    # TODO: Require that Rails loggers accept a block.
-    class DelayedLog < ActiveSupport::BasicObject
-      def initialize(&block)
-        @str, @block = nil, block
-      end
-
-      def method_missing(*args, &block)
-        unless @str
-          @str, @block = @block.call, nil
-        end
-        @str.send(*args, &block)
-      end
-    end
   end
 end
diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb
index dbba69f637..67656110c4 100644
--- a/actionpack/lib/action_controller/base.rb
+++ b/actionpack/lib/action_controller/base.rb
@@ -15,7 +15,6 @@ module ActionController
     include ActionController::ConditionalGet
     include ActionController::RackDelegation
     include ActionController::Logger
-    include ActionController::Benchmarking
     include ActionController::Configuration
 
     # Legacy modules
diff --git a/actionpack/lib/action_controller/caching.rb b/actionpack/lib/action_controller/caching.rb
index d784138ebe..69ed84da95 100644
--- a/actionpack/lib/action_controller/caching.rb
+++ b/actionpack/lib/action_controller/caching.rb
@@ -60,6 +60,17 @@ module ActionController #:nodoc:
       def cache_configured?
         perform_caching && cache_store
       end
+
+      def log_event(name, before, after, instrumenter_id, payload)
+        if name.to_s =~ /(read|write|cache|expire|exist)_(fragment|page)\??/
+          key_or_path = payload[:key] || payload[:path]
+          human_name  = name.to_s.humanize
+          duration    = (after - before) * 1000
+          logger.info("#{human_name} #{key_or_path.inspect} (%.1fms)" % duration)
+        else
+          super
+        end
+      end
     end
 
     def caching_allowed?
diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb
index 8c1167d526..f569d0dd8b 100644
--- a/actionpack/lib/action_controller/caching/fragments.rb
+++ b/actionpack/lib/action_controller/caching/fragments.rb
@@ -74,7 +74,7 @@ module ActionController #:nodoc:
         return unless cache_configured?
         key = fragment_cache_key(key)
 
-        ActiveSupport::Notifications.instrument(:fragment_exist?, :key => key) do
+        ActiveSupport::Notifications.instrument(:exist_fragment?, :key => key) do
           cache_store.exist?(key, options)
         end
       end
diff --git a/actionpack/lib/action_controller/metal/active_record_runtime.rb b/actionpack/lib/action_controller/metal/active_record_runtime.rb
new file mode 100644
index 0000000000..29f6dcc783
--- /dev/null
+++ b/actionpack/lib/action_controller/metal/active_record_runtime.rb
@@ -0,0 +1,27 @@
+module ActionController
+  module ActiveRecordRuntime
+    extend ActiveSupport::Concern
+
+    attr_internal :db_runtime
+
+    def cleanup_view_runtime
+      if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
+        db_rt_before_render = ActiveRecord::Base.connection.reset_runtime
+        runtime = super
+        db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
+        self.db_runtime = db_rt_before_render + db_rt_after_render
+        runtime - db_rt_after_render
+      else
+        super
+      end
+    end
+
+    module ClassMethods
+      def process_log_action(controller)
+        super
+        db_runtime = controller.send :db_runtime
+        logger.info("  ActiveRecord runtime: %.1fms" % db_runtime.to_f) if db_runtime
+      end
+    end
+  end
+end
\ No newline at end of file
diff --git a/actionpack/lib/action_controller/metal/benchmarking.rb b/actionpack/lib/action_controller/metal/benchmarking.rb
deleted file mode 100644
index f73f635b0d..0000000000
--- a/actionpack/lib/action_controller/metal/benchmarking.rb
+++ /dev/null
@@ -1,72 +0,0 @@
-require 'active_support/core_ext/benchmark'
-
-module ActionController #:nodoc:
-  # The benchmarking module times the performance of actions and reports to the logger. If the Active Record
-  # package has been included, a separate timing section for database calls will be added as well.
-  module Benchmarking #:nodoc:
-    extend ActiveSupport::Concern
-
-    protected
-      def render(*args, &block)
-        if logger
-          if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-            db_runtime = ActiveRecord::Base.connection.reset_runtime
-          end
-
-          render_output = nil
-          @view_runtime = Benchmark.ms { render_output = super }
-
-          if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-            @db_rt_before_render = db_runtime
-            @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
-            @view_runtime -= @db_rt_after_render
-          end
-
-          render_output
-        else
-          super
-        end
-      end
-
-    private
-      def process_action(*args)
-        if logger
-          ms = [Benchmark.ms { super }, 0.01].max
-          logging_view          = defined?(@view_runtime)
-          logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
-
-          log_message  = 'Completed in %.0fms' % ms
-
-          if logging_view || logging_active_record
-            log_message << " ("
-            log_message << view_runtime if logging_view
-
-            if logging_active_record
-              log_message << ", " if logging_view
-              log_message << active_record_runtime + ")"
-            else
-              ")"
-            end
-          end
-
-          log_message << " | #{response.status}"
-          log_message << " [#{complete_request_uri rescue "unknown"}]"
-
-          logger.info(log_message)
-        else
-          super
-        end
-      end
-
-      def view_runtime
-        "View: %.0f" % @view_runtime
-      end
-
-      def active_record_runtime
-        db_runtime = ActiveRecord::Base.connection.reset_runtime
-        db_runtime += @db_rt_before_render if @db_rt_before_render
-        db_runtime += @db_rt_after_render if @db_rt_after_render
-        "DB: %.0f" % db_runtime
-      end
-  end
-end
diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
index a53c052075..59e200396a 100644
--- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
+++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
@@ -2,8 +2,6 @@ module ActionController
   module FilterParameterLogging
     extend ActiveSupport::Concern
 
-    include AbstractController::Logger
-
     module ClassMethods
       # Replace sensitive parameter data from the request log.
       # Filters parameters that have any of the arguments as a substring.
@@ -54,23 +52,25 @@ module ActionController
         end
         protected :filter_parameters
       end
-    end
 
-    INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path]
+    protected
 
-    def process(*)
-      response = super
-      if logger
-        parameters = filter_parameters(params).except!(*INTERNAL_PARAMS)
-        logger.info { "  Parameters: #{parameters.inspect}" } unless parameters.empty?
+      # Overwrite log_process_action to include parameters information.
+      # If this method is invoked, it means logger is defined, so don't
+      # worry with such scenario here.
+      def log_process_action(controller) #:nodoc:
+        params = controller.send(:filter_parameters, controller.request.params)
+        logger.info "  Parameters: #{params.inspect}" unless params.empty?
+        super
       end
-      response
     end
 
+    INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path]
+
   protected
 
     def filter_parameters(params)
-      params.dup
+      params.dup.except!(*INTERNAL_PARAMS)
     end
 
   end
diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb
index 956d7dd371..5d14f6c9c9 100644
--- a/actionpack/lib/action_controller/metal/logger.rb
+++ b/actionpack/lib/action_controller/metal/logger.rb
@@ -1,34 +1,74 @@
 require 'abstract_controller/logger'
 
 module ActionController
+  # Adds instrumentation to <tt>process_action</tt> and a <tt>log_event</tt> method
+  # responsible to log events from ActiveSupport::Notifications. This module handles
+  # :process_action and :render_template events but allows any other module to hook
+  # into log_event and provide its own logging facilities (as in ActionController::Caching).
   module Logger
-    # Override process_action in the AbstractController::Base
-    # to log details about the method.
+    extend ActiveSupport::Concern
+
+    attr_internal :view_runtime
+
     def process_action(action)
-      result = ActiveSupport::Notifications.instrument(:process_action,
-                :controller => self, :action => action) do
+      ActiveSupport::Notifications.instrument(:process_action, :controller => self, :action => action) do
         super
       end
+    end
 
+    def render(*args, &block)
       if logger
-        log = AbstractController::Logger::DelayedLog.new do
-          "\n\nProcessing #{self.class.name}\##{action_name} " \
-          "to #{request.formats} (for #{request_origin}) " \
-          "[#{request.method.to_s.upcase}]"
+        render_output = nil
+
+        self.view_runtime = cleanup_view_runtime do
+          Benchmark.ms { render_output = super }
         end
 
-        logger.info(log)
+        render_output
+      else
+        super
       end
+    end
 
-      result
+    def cleanup_view_runtime
+      yield
     end
 
-  private
+    module ClassMethods
+      def log_event(name, before, after, instrumenter_id, payload)
+        if name == :process_action
+          duration     = [(after - before) * 1000, 0.01].max
+          controller   = payload[:controller]
+          request      = controller.request
+
+          logger.info "\n\nProcessed #{controller.class.name}##{payload[:action]} " \
+            "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \
+            "[#{request.method.to_s.upcase}]"
 
-    # Returns the request origin with the IP and time. This needs to be cached,
-    # otherwise we would get different results for each time it calls.
-    def request_origin
-      @request_origin ||= "#{request.remote_ip} at #{Time.now.to_s(:db)}"
+          log_process_action(controller)
+
+          message = "Completed in %.0fms" % duration
+          message << " | #{controller.response.status}"
+          message << " [#{request.request_uri rescue "unknown"}]"
+
+          logger.info(message)
+        elsif name == :render_template
+          # TODO Make render_template logging work if you are using just ActionView
+          duration = (after - before) * 1000
+          message = "Rendered #{payload[:identifier]}"
+          message << " within #{payload[:layout]}" if payload[:layout]
+          message << (" (%.1fms)" % duration)
+          logger.info(message)
+        end
+      end
+
+    protected
+
+      # A hook which allows logging what happened during controller process action.
+      def log_process_action(controller) #:nodoc:
+        view_runtime = controller.send :view_runtime
+        logger.info("  View runtime: %.1fms" % view_runtime.to_f) if view_runtime
+      end
     end
   end
 end
diff --git a/actionpack/lib/action_controller/rails.rb b/actionpack/lib/action_controller/rails.rb
index 36a52b3149..e381828ee4 100644
--- a/actionpack/lib/action_controller/rails.rb
+++ b/actionpack/lib/action_controller/rails.rb
@@ -14,10 +14,6 @@ module ActionController
     end
 
     # Routing must be initialized after plugins to allow the former to extend the routes
-    # ---
-    # If Action Controller is not one of the loaded frameworks (Configuration#frameworks)
-    # this does nothing. Otherwise, it loads the routing definitions and sets up
-    # loading module used to lazily load controllers (Configuration#controller_paths).
     initializer "action_controller.initialize_routing" do |app|
       app.route_configuration_files << app.config.routes_configuration_file
       app.route_configuration_files << app.config.builtin_routes_configuration_file
@@ -88,13 +84,8 @@ module ActionController
     initializer "action_controller.notifications" do |app|
       require 'active_support/notifications'
 
-      ActiveSupport::Notifications.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |*args|
-        event = ActiveSupport::Notifications::Event.new(*args)
-
-        if logger = ActionController::Base.logger
-          human_name = event.name.to_s.humanize
-          logger.info("#{human_name} (%.1fms)" % event.duration)
-        end
+      ActiveSupport::Notifications.subscribe do |*args|
+        ActionController::Base.log_event(*args) if ActionController::Base.logger
       end
     end
 
diff --git a/actionpack/lib/action_view/render/rendering.rb b/actionpack/lib/action_view/render/rendering.rb
index 5e7dd3e2df..0302e44b4e 100644
--- a/actionpack/lib/action_view/render/rendering.rb
+++ b/actionpack/lib/action_view/render/rendering.rb
@@ -107,12 +107,6 @@ module ActionView
     end
 
     def _render_template(template, layout = nil, options = {}, partial = nil)
-      logger && logger.info do
-        msg = "Rendering #{template.inspect}"
-        msg << " (#{options[:status]})" if options[:status]
-        msg
-      end
-
       locals = options[:locals] || {}
 
       content = ActiveSupport::Notifications.instrument(:render_template,
@@ -124,8 +118,7 @@ module ActionView
 
       if layout
         @_layout = layout.identifier
-        logger.info("Rendering template within #{layout.inspect}") if logger
-        content = _render_layout(layout, locals)
+        content  = _render_layout(layout, locals)
       end
 
       content