Add subscriber for ActionPack and move all logging inside it.

9 files changed, 149 insertions, 133 deletions

diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb
index 746ab3e6db..4f564a6377 100644
--- a/actionpack/lib/action_controller/base.rb
+++ b/actionpack/lib/action_controller/base.rb
@@ -15,7 +15,6 @@ module ActionController
     include ActionController::Renderers::All
     include ActionController::ConditionalGet
     include ActionController::RackDelegation
-    include ActionController::Logger
     include ActionController::Configuration
 
     # Legacy modules
@@ -36,6 +35,10 @@ module ActionController
     include ActionController::FilterParameterLogging
     include ActionController::Translation
 
+    # Add instrumentations hooks at the bottom, to ensure they instrument
+    # all the methods properly.
+    include ActionController::Instrumentation
+
     # TODO: Extract into its own module
     # This should be moved together with other normalizing behavior
     module ImplicitRender
diff --git a/actionpack/lib/action_controller/caching.rb b/actionpack/lib/action_controller/caching.rb
index 5c0d754ad6..d784138ebe 100644
--- a/actionpack/lib/action_controller/caching.rb
+++ b/actionpack/lib/action_controller/caching.rb
@@ -60,17 +60,6 @@ module ActionController #:nodoc:
       def cache_configured?
         perform_caching && cache_store
       end
-
-      def log_event(name, before, after, instrumenter_id, payload)
-        if name.to_s =~ /action_controller\.((read|write|expire|exist)_(fragment|page)\??)/
-          key_or_path = payload[:key] || payload[:path]
-          human_name  = $1.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/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
index 59e200396a..9e03f50759 100644
--- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
+++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb
@@ -2,6 +2,8 @@ module ActionController
   module FilterParameterLogging
     extend ActiveSupport::Concern
 
+    INTERNAL_PARAMS = %w(controller action format _method only_path)
+
     module ClassMethods
       # Replace sensitive parameter data from the request log.
       # Filters parameters that have any of the arguments as a substring.
@@ -48,25 +50,12 @@ module ActionController
             filtered_params[key] = value
           end
 
-          filtered_params
+          filtered_params.except!(*INTERNAL_PARAMS)
         end
         protected :filter_parameters
       end
-
-    protected
-
-      # 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
     end
 
-    INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path]
-
   protected
 
     def filter_parameters(params)
diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb
new file mode 100644
index 0000000000..91d454f0c3
--- /dev/null
+++ b/actionpack/lib/action_controller/metal/instrumentation.rb
@@ -0,0 +1,77 @@
+require 'abstract_controller/logger'
+
+module ActionController
+  # Adds instrumentation to several ends in ActionController::Base. It also provides
+  # some hooks related with process_action logging and view runtime.
+  module Instrumentation
+    extend ActiveSupport::Concern
+
+    included do
+      include AbstractController::Logger
+    end
+
+    attr_internal :view_runtime
+
+    def process_action(action, *args)
+      ActiveSupport::Notifications.instrument("action_controller.process_action",
+        :controller => self, :action => action) do
+        super
+      end
+    end
+
+    def render(*args, &block)
+      if logger
+        render_output = nil
+
+        self.view_runtime = cleanup_view_runtime do
+          Benchmark.ms { render_output = super }
+        end
+
+        render_output
+      else
+        super
+      end
+    end
+
+    def send_file(path, options={})
+      ActiveSupport::Notifications.instrument("action_controller.send_file",
+        options.merge(:path => path)) do
+        super
+      end
+    end
+
+    def send_data(data, options = {})
+      ActiveSupport::Notifications.instrument("action_controller.send_data", options) do
+        super
+      end
+    end
+
+    def redirect_to(*args)
+      super
+      ActiveSupport::Notifications.instrument("action_controller.redirect_to",
+        :status => self.status, :location => self.location)
+    end
+
+    # A hook which allows you to clean up any time taken into account in
+    # views wrongly, like database querying time.
+    #
+    #   def cleanup_view_runtime
+    #     super - time_taken_in_something_expensive
+    #   end
+    #
+    # :api: plugin
+    def cleanup_view_runtime #:nodoc:
+      yield
+    end
+
+    module ClassMethods
+      # A hook which allows other frameworks to log what happened during
+      # controller process action.
+      # :api: plugin
+      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
\ No newline at end of file
diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb
deleted file mode 100644
index e995d6bcea..0000000000
--- a/actionpack/lib/action_controller/metal/logger.rb
+++ /dev/null
@@ -1,93 +0,0 @@
-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
-    extend ActiveSupport::Concern
-
-    included do
-      include AbstractController::Logger
-    end
-
-    attr_internal :view_runtime
-
-    def process_action(action)
-      ActiveSupport::Notifications.instrument("action_controller.process_action",
-        :controller => self, :action => action) do
-        super
-      end
-    end
-
-    def render(*args, &block)
-      if logger
-        render_output = nil
-
-        self.view_runtime = cleanup_view_runtime do
-          Benchmark.ms { render_output = super }
-        end
-
-        render_output
-      else
-        super
-      end
-    end
-
-    # If you want to remove any time taken into account in :view_runtime
-    # wrongly, you can do it here:
-    #
-    #   def cleanup_view_runtime
-    #     super - time_taken_in_something_expensive
-    #   end
-    #
-    # :api: plugin
-    def cleanup_view_runtime #:nodoc:
-      yield
-    end
-
-    module ClassMethods
-      # This is the hook invoked by ActiveSupport::Notifications.subscribe.
-      # If you need to log any event, overwrite the method and do it here.
-      def log_event(name, before, after, instrumenter_id, payload) #:nodoc:
-        if name == "action_controller.process_action"
-          duration     = [(after - before) * 1000, 0.01].max
-          controller   = payload[:controller]
-          request      = controller.request
-
-          logger.info "\nProcessed #{controller.class.name}##{payload[:action]} " \
-            "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \
-            "[#{request.method.to_s.upcase}]"
-
-          log_process_action(controller)
-
-          message = "Completed in %.0fms" % duration
-          message << " | #{controller.response.status}"
-          message << " [#{request.request_uri rescue "unknown"}]\n\n"
-
-          logger.info(message)
-        elsif name == "action_view.render_template"
-          duration = (after - before) * 1000
-          message = "Rendered #{from_rails_root(payload[:identifier])}"
-          message << " within #{from_rails_root(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.
-      # :api: plugin
-      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
-
-      def from_rails_root(string)
-        defined?(Rails.root) ? string.sub("#{Rails.root}/app/views/", "") : string
-      end
-    end
-  end
-end
\ No newline at end of file
diff --git a/actionpack/lib/action_controller/metal/redirecting.rb b/actionpack/lib/action_controller/metal/redirecting.rb
index 7b277c0ae0..faf0589fd2 100644
--- a/actionpack/lib/action_controller/metal/redirecting.rb
+++ b/actionpack/lib/action_controller/metal/redirecting.rb
@@ -57,8 +57,6 @@ module ActionController
       self.status        = _extract_redirect_to_status(options, response_status)
       self.location      = _compute_redirect_to_location(options)
       self.response_body = "<html><body>You are being <a href=\"#{ERB::Util.h(location)}\">redirected</a>.</body></html>"
-
-      logger.info("Redirected to #{location}") if logger && logger.info?
     end
 
     private
diff --git a/actionpack/lib/action_controller/metal/streaming.rb b/actionpack/lib/action_controller/metal/streaming.rb
index 288b5d7c99..8f03b8bb17 100644
--- a/actionpack/lib/action_controller/metal/streaming.rb
+++ b/actionpack/lib/action_controller/metal/streaming.rb
@@ -88,13 +88,11 @@ module ActionController #:nodoc:
         @performed_render = false
 
         if options[:x_sendfile]
-          logger.info "Sending #{X_SENDFILE_HEADER} header #{path}" if logger
           head options[:status], X_SENDFILE_HEADER => path
         else
           if options[:stream]
             # TODO : Make render :text => proc {} work with the new base
             render :status => options[:status], :text => Proc.new { |response, output|
-              logger.info "Streaming file #{path}" unless logger.nil?
               len = options[:buffer_size] || 4096
               File.open(path, 'rb') do |file|
                 while buf = file.read(len)
@@ -103,7 +101,6 @@ module ActionController #:nodoc:
               end
             }
           else
-            logger.info "Sending file #{path}" unless logger.nil?
             File.open(path, 'rb') { |file| render :status => options[:status], :text => file.read }
           end
         end
@@ -141,7 +138,6 @@ module ActionController #:nodoc:
       # data to the browser, then use <tt>render :text => proc { ... }</tt>
       # instead. See ActionController::Base#render for more information.
       def send_data(data, options = {}) #:doc:
-        logger.info "Sending data #{options[:filename]}" if logger
         send_file_headers! options.merge(:length => data.bytesize)
         render :status => options[:status], :text => data
       end
diff --git a/actionpack/lib/action_controller/railtie.rb b/actionpack/lib/action_controller/railtie.rb
index 42257f9400..d4886ecefd 100644
--- a/actionpack/lib/action_controller/railtie.rb
+++ b/actionpack/lib/action_controller/railtie.rb
@@ -5,6 +5,9 @@ module ActionController
   class Railtie < Rails::Railtie
     plugin_name :action_controller
 
+    require "action_controller/railties/subscriber"
+    subscriber ActionController::Railties::Subscriber.new
+
     initializer "action_controller.set_configs" do |app|
       app.config.action_controller.each do |k,v|
         ActionController::Base.send "#{k}=", v
@@ -86,13 +89,5 @@ module ActionController
       end
     end
 
-    initializer "action_controller.notifications" do |app|
-      require 'active_support/notifications'
-
-      ActiveSupport::Notifications.subscribe do |*args|
-        ActionController::Base.log_event(*args) if ActionController::Base.logger
-      end
-    end
-
   end
 end
diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb
new file mode 100644
index 0000000000..d9d77304ee
--- /dev/null
+++ b/actionpack/lib/action_controller/railties/subscriber.rb
@@ -0,0 +1,62 @@
+module ActionController
+  module Railties
+    class Subscriber < Rails::Subscriber
+      def process_action(event)
+        controller = event.payload[:controller]
+        request    = controller.request
+
+        info "\nProcessed #{controller.class.name}##{event.payload[:action]} " \
+          "to #{request.formats} (for #{request.remote_ip} at #{event.time.to_s(:db)}) " \
+          "[#{request.method.to_s.upcase}]"
+
+        params = controller.send(:filter_parameters, request.params)
+        info "  Parameters: #{params.inspect}" unless params.empty?
+
+        ActionController::Base.log_process_action(controller)
+
+        message = "Completed in %.0fms" % event.duration
+        message << " | #{controller.response.status}"
+        message << " [#{request.request_uri rescue "unknown"}]\n\n"
+
+        info(message)
+      end
+
+      def send_file(event)
+        message = if event.payload[:x_sendfile]
+          header = ActionController::Streaming::X_SENDFILE_HEADER
+          "Sending #{header} header %s"
+        elsif event.payload[:stream]
+          "Streaming file %s"
+        else
+          "Sending file %s"
+        end
+
+        message << " (%.1fms)"
+        info(message % [event.payload[:path], event.duration])
+      end
+
+      def redirect_to(event)
+        info "Redirected to #{event.payload[:location]} with status #{event.payload[:status]}"
+      end
+
+      def send_data(event)
+        info("Sending data %s (%.1fms)" % [event.payload[:filename], event.duration])
+      end
+
+      %w(write_fragment read_fragment exist_fragment?
+         expire_fragment expire_page write_page).each do |method|
+        class_eval <<-METHOD, __FILE__, __LINE__ + 1
+          def #{method}(event)
+            key_or_path = event.payload[:key] || event.payload[:path]
+            human_name  = #{method.to_s.humanize.inspect}
+            info("\#{human_name} \#{key_or_path.inspect} (%.1fms)" % event.duration)
+          end
+        METHOD
+      end
+
+      def logger
+        ActionController::Base.logger
+      end
+    end
+  end
+end
\ No newline at end of file