1 files changed, 55 insertions, 15 deletions
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