Remove ActionView inline logging to ActiveSupport::Notifications and create...

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.

actionpack/lib/abstract_controller/logger.rb

@@ -9,25 +9,5 @@ module Logger
       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

actionpack/lib/action_controller/base.rb

@@ -15,7 +15,6 @@ class Base < Metal
     include ActionController::ConditionalGet
     include ActionController::RackDelegation
     include ActionController::Logger
-    include ActionController::Benchmarking
     include ActionController::Configuration
 
     # Legacy modules

actionpack/lib/action_controller/caching.rb

@@ -60,6 +60,17 @@ module ClassMethods
       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?

actionpack/lib/action_controller/caching/fragments.rb

@@ -74,7 +74,7 @@ def fragment_exist?(key, options = nil)
         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

actionpack/lib/action_controller/metal/active_record_runtime.rb

+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

actionpack/lib/action_controller/metal/benchmarking.rb

-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

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 @@ def filter_parameter_logging(*filter_words, &block)
         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

actionpack/lib/action_controller/metal/logger.rb

 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

actionpack/lib/action_controller/rails.rb

@@ -14,10 +14,6 @@ class Plugin < Rails::Plugin
     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 @@ class Plugin < Rails::Plugin
     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
 

actionpack/lib/action_view/render/rendering.rb

@@ -107,12 +107,6 @@ def render_template(options)
     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 @@ def _render_template(template, layout = nil, options = {}, partial = nil)
 
       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

actionpack/test/abstract_unit.rb

@@ -50,6 +50,14 @@
 FIXTURE_LOAD_PATH = File.join(File.dirname(__FILE__), 'fixtures')
 FIXTURES = Pathname.new(FIXTURE_LOAD_PATH)
 
+# Turn on notifications
+require 'active_support/notifications'
+Thread.abort_on_exception = true
+
+ActiveSupport::Notifications.subscribe do |*args|
+  ActionController::Base.log_event(*args) if ActionController::Base.logger
+end
+
 module SetupOnce
   extend ActiveSupport::Concern
 
@@ -87,6 +95,21 @@ class ActiveSupport::TestCase
   end
 end
 
+class MockLogger
+  attr_reader :logged
+  attr_accessor :level
+
+  def initialize
+    @level = Logger::DEBUG
+    @logged = []
+  end
+
+  def method_missing(method, *args, &blk)
+    @logged << args.first
+    @logged << blk.call if block_given?
+  end
+end
+
 class ActionController::IntegrationTest < ActiveSupport::TestCase
   def self.build_app(routes = nil)
     ActionDispatch::MiddlewareStack.new { |middleware|

actionpack/test/controller/base_test.rb

@@ -158,13 +158,6 @@ def test_get_on_hidden_should_fail
     assert_raise(ActionController::UnknownAction) { get :hidden_action }
     assert_raise(ActionController::UnknownAction) { get :another_hidden_action }
   end
-
-  def test_namespaced_action_should_log_module_name
-    use_controller Submodule::ContainedNonEmptyController
-    @controller.logger = MockLogger.new
-    get :public_action
-    assert_match /Processing\sSubmodule::ContainedNonEmptyController#public_action/, @controller.logger.logged[1]
-  end
 end
 
 class DefaultUrlOptionsTest < ActionController::TestCase

actionpack/test/controller/benchmark_test.rb

-require 'abstract_unit'
-
-# Provide some static controllers.
-class BenchmarkedController < ActionController::Base
-  def public_action
-    render :nothing => true
-  end
-
-  def rescue_action(e)
-    raise e
-  end
-end
-
-class BenchmarkTest < ActionController::TestCase
-  tests BenchmarkedController
-
-  class MockLogger
-    def method_missing(*args)
-    end
-  end
-
-  def setup
-    super
-    # benchmark doesn't do anything unless a logger is set
-    @controller.logger = MockLogger.new
-    @request.host = "test.actioncontroller.i"
-  end
-
-  def test_with_http_1_0_request
-    @request.host = nil
-    assert_nothing_raised { get :public_action }
-  end
-end

actionpack/test/controller/caching_test.rb

@@ -640,7 +640,7 @@ def test_fragment_for_logging
     assert fragment_computed
     assert_equal 'generated till now -> ', buffer
     ActiveSupport::Notifications.notifier.wait
-    assert_equal [:fragment_exist?, :write_fragment], events.map(&:first)
+    assert_equal [:exist_fragment?, :write_fragment], events.map(&:first)
   end
 
 end

actionpack/test/controller/filter_params_test.rb

@@ -70,9 +70,9 @@ def test_filter_parameters_inside_logs
     FilterParamController.filter_parameter_logging(:lifo, :amount)
 
     get :payment, :lifo => 'Pratik', :amount => '420', :step => '1'
+    ActiveSupport::Notifications.notifier.wait
 
     filtered_params_logs = logs.detect {|l| l =~ /\AParameters/ }
-
     assert filtered_params_logs.index('"amount"=>"[FILTERED]"')
     assert filtered_params_logs.index('"lifo"=>"[FILTERED]"')
     assert filtered_params_logs.index('"step"=>"1"')

actionpack/test/controller/logging_test.rb

 require 'abstract_unit'
 
-class LoggingController < ActionController::Base
-  def show
-    render :nothing => true
-  end
-end
-
-class LoggingTest < ActionController::TestCase
-  tests LoggingController
-
-  class MockLogger
-    attr_reader :logged
-    attr_accessor :level
+module Another
+  class LoggingController < ActionController::Base
+    layout "layouts/standard"
 
-    def initialize
-      @level = Logger::DEBUG
+    def show
+      render :nothing => true
     end
 
-    def method_missing(method, *args, &blk)
-      @logged ||= []
-      @logged << args.first
-      @logged << blk.call if block_given?
+    def with_layout
+      render :template => "test/hello_world", :layout => true
     end
   end
+end
+
+class LoggingTest < ActionController::TestCase
+  tests Another::LoggingController
 
   def setup
     super
     set_logger
   end
 
+  def get(*args)
+    super
+    wait
+  end
+
+  def wait
+    ActiveSupport::Notifications.notifier.wait
+  end
+
   def test_logging_without_parameters
     get :show
-    assert_equal 3, logs.size
+    assert_equal 4, logs.size
     assert_nil logs.detect {|l| l =~ /Parameters/ }
   end
 
   def test_logging_with_parameters
     get :show, :id => '10'
-    assert_equal 4, logs.size
+    assert_equal 5, logs.size
 
     params = logs.detect {|l| l =~ /Parameters/ }
     assert_equal 'Parameters: {"id"=>"10"}', params
   end
 
+  def test_log_controller_with_namespace_and_action
+    get :show
+    assert_match /Processed\sAnother::LoggingController#show/, logs[1]
+  end
+
+  def test_log_view_runtime
+     get :show
+     assert_match /View runtime/, logs[2]
+   end
+
+  def test_log_completed_status_and_request_uri
+    get :show
+    last = logs.last
+    assert_match /Completed/, last
+    assert_match /200/, last
+    assert_match /another\/logging\/show/, last
+  end
+
+  def test_logger_prints_layout_and_template_rendering_info
+    get :with_layout
+    logged = logs.find {|l| l =~ /render/i }
+    assert_match /Rendered (.*)test\/hello_world.erb within (.*)layouts\/standard.html.erb/, logged
+  end
+
   private
     def set_logger
       @controller.logger = MockLogger.new

actionpack/test/controller/render_test.rb

@@ -10,19 +10,6 @@ def hello_world
   end
 end
 
-class MockLogger
-  attr_reader :logged
-
-  def initialize
-    @logged = []
-  end
-
-  def method_missing(method, *args, &blk)
-    @logged << args.first
-    @logged << blk.call if block_given?
-  end
-end
-
 class TestController < ActionController::Base
   protect_from_forgery
 
@@ -1500,21 +1487,4 @@ def test_last_modified_works_with_less_than_too
     get :conditional_hello_with_bangs
     assert_response :success
   end
-end
-
-class RenderingLoggingTest < ActionController::TestCase
-  tests TestController
-
-  def setup
-    super
-    @request.host = "www.nextangle.com"
-  end
-
-  def test_logger_prints_layout_and_template_rendering_info
-    @controller.logger = MockLogger.new
-    get :layout_test
-    logged = @controller.logger.logged.find_all {|l| l =~ /render/i }
-    assert logged[0] =~ %r{Rendering.*test/hello_world}
-    assert logged[1] =~ %r{Rendering template within.*layouts/standard}
-  end
-end
+end
\ No newline at end of file

activerecord/lib/active_record/rails.rb

@@ -50,8 +50,8 @@ class Plugin < Rails::Plugin
     initializer "active_record.notifications" do
       require 'active_support/notifications'
 
-      ActiveSupport::Notifications.subscribe("sql") do |name, before, after, result, instrumenter_id, payload|
-        ActiveRecord::Base.connection.log_info(payload[:sql], name, after - before)
+      ActiveSupport::Notifications.subscribe("sql") do |name, before, after, instrumenter_id, payload|
+        ActiveRecord::Base.connection.log_info(payload[:sql], payload[:name], (after - before) * 1000)
       end
     end
 

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -10,10 +10,10 @@ def initialize(notifier)
       end
 
       def instrument(name, payload={})
-        time   = Time.now
-        result = yield if block_given?
+        time = Time.now
+        yield if block_given?
       ensure
-        @notifier.publish(name, time, Time.now, result, @id, payload)
+        @notifier.publish(name, time, Time.now, @id, payload)
       end
 
       private
@@ -23,15 +23,14 @@ def unique_id
     end
 
     class Event
-      attr_reader :name, :time, :end, :transaction_id, :result, :payload
+      attr_reader :name, :time, :end, :transaction_id, :payload
 
-      def initialize(name, start, ending, result, transaction_id, payload)
+      def initialize(name, start, ending, transaction_id, payload)
         @name           = name
         @payload        = payload.dup
         @time           = start
         @transaction_id = transaction_id
         @end            = ending
-        @result         = result
       end
 
       def duration

activesupport/test/notifications_test.rb

@@ -134,27 +134,25 @@ def test_event_is_pushed_even_without_block
 
   class EventTest < TestCase
     def test_events_are_initialized_with_details
-      event = event(:foo, Time.now, Time.now + 1, 1, random_id, :payload => :bar)
-      assert_equal :foo, event.name
-      assert_equal Hash[:payload => :bar], event.payload
-    end
-
-    def test_events_consumes_information_given_as_payload
       time = Time.now
-      event = event(:foo, time, time + 0.01, 1, random_id, {})
+      event = event(:foo, time, time + 0.01, random_id, {})
 
-      assert_equal Hash.new, event.payload
+      assert_equal :foo, event.name
       assert_equal time, event.time
-      assert_equal 1, event.result
       assert_equal 10.0, event.duration
     end
 
+    def test_events_consumes_information_given_as_payload
+      event = event(:foo, Time.now, Time.now + 1, random_id, :payload => :bar)
+      assert_equal Hash[:payload => :bar], event.payload
+    end
+
     def test_event_is_parent_based_on_time_frame
       time = Time.utc(2009, 01, 01, 0, 0, 1)
 
-      parent    = event(:foo, Time.utc(2009), Time.utc(2009) + 100, nil, random_id, {})
-      child     = event(:foo, time, time + 10, nil, random_id, {})
-      not_child = event(:foo, time, time + 100, nil, random_id, {})
+      parent    = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id, {})
+      child     = event(:foo, time, time + 10, random_id, {})
+      not_child = event(:foo, time, time + 100, random_id, {})
 
       assert parent.parent_of?(child)
       assert !child.parent_of?(parent)