Add subscriber for ActionPack and move all logging inside it.

actionpack/lib/action_controller.rb

@@ -23,7 +23,7 @@ module ActionController
     autoload :Helpers
     autoload :HideActions
     autoload :HttpAuthentication
-    autoload :Logger
+    autoload :Instrumentation
     autoload :MimeResponds
     autoload :RackDelegation
     autoload :Redirecting

actionpack/lib/action_controller/base.rb

@@ -15,7 +15,6 @@ class Base < Metal
     include ActionController::Renderers::All
     include ActionController::ConditionalGet
     include ActionController::RackDelegation
-    include ActionController::Logger
     include ActionController::Configuration
 
     # Legacy modules
@@ -36,6 +35,10 @@ class Base < Metal
     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

actionpack/lib/action_controller/caching.rb

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

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

actionpack/lib/action_controller/metal/logger.rb → actionpack/lib/action_controller/metal/instrumentation.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
+  # 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
@@ -14,7 +12,7 @@ module Logger
 
     attr_internal :view_runtime
 
-    def process_action(action)
+    def process_action(action, *args)
       ActiveSupport::Notifications.instrument("action_controller.process_action",
         :controller => self, :action => action) do
         super
@@ -35,8 +33,27 @@ def render(*args, &block)
       end
     end
 
-    # If you want to remove any time taken into account in :view_runtime
-    # wrongly, you can do it here:
+    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
@@ -48,46 +65,13 @@ def cleanup_view_runtime #:nodoc:
     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.
+      # 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
-
-      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

actionpack/lib/action_controller/metal/redirecting.rb

@@ -57,8 +57,6 @@ def redirect_to(options = {}, response_status = {}) #:doc:
       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

actionpack/lib/action_controller/metal/streaming.rb

@@ -88,13 +88,11 @@ def send_file(path, options = {}) #:doc:
         @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 @@ def send_file(path, options = {}) #:doc:
               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 @@ def send_file(path, options = {}) #:doc:
       # 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

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 @@ def name
       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

actionpack/lib/action_controller/railties/subscriber.rb

+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

actionpack/lib/action_view/railtie.rb

 require "action_view"
-require "rails"
\ No newline at end of file
+require "rails"
+
+module ActionView
+  class Railtie < Rails::Railtie
+    plugin_name :action_view
+
+    require "action_view/railties/subscriber"
+    subscriber ActionView::Railties::Subscriber.new
+  end
+end
\ No newline at end of file

actionpack/lib/action_view/railties/subscriber.rb

+module ActionView
+  module Railties
+    class Subscriber < Rails::Subscriber
+      def render_template(event)
+        message = "Rendered #{from_rails_root(event.payload[:identifier])}"
+        message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
+        message << (" (%.1fms)" % event.duration)
+        info(message)        
+      end
+      alias :render_partial :render_template
+      alias :render_collection :render_template
+
+      def logger
+        ActionController::Base.logger
+      end
+
+    protected
+
+      def from_rails_root(string)
+        string.sub("#{Rails.root}/", "").sub(/^app\/views\//, "")
+      end
+    end
+  end
+end
\ No newline at end of file

actionpack/lib/action_view/template/text.rb

@@ -13,7 +13,7 @@ def details
       end
 
       def identifier
-        self
+        'text template'
       end
 
       def inspect

actionpack/test/abstract_unit.rb

@@ -48,14 +48,6 @@
 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
 
@@ -93,24 +85,6 @@ class ActiveSupport::TestCase
   end
 end
 
-class MockLogger
-  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
-
-  def logged
-    @logged.compact.map { |l| l.to_s.strip }
-  end
-end
-
 class ActionController::IntegrationTest < ActiveSupport::TestCase
   def self.build_app(routes = nil)
     ActionDispatch::MiddlewareStack.new { |middleware|

actionpack/test/controller/caching_test.rb

@@ -629,20 +629,6 @@ def test_fragment_for
     assert_equal 'generated till now -> fragment content', buffer
   end
 
-  def test_fragment_for_logging
-    # Wait pending notifications to be published
-    ActiveSupport::Notifications.notifier.wait
-    @controller.logger = MockLogger.new
-
-    fragment_computed = false
-    @controller.fragment_for('buffer', 'expensive') { fragment_computed = true }
-    ActiveSupport::Notifications.notifier.wait
-
-    assert fragment_computed
-    assert_match /Exist fragment\? "views\/expensive"/, @controller.logger.logged[0]
-    assert_match /Write fragment "views\/expensive"/, @controller.logger.logged[1]
-  end
-
 end
 
 class FunctionalCachingController < ActionController::Base

actionpack/test/controller/filter_params_test.rb

@@ -66,18 +66,6 @@ def test_filter_parameters_is_protected
     assert_raise(NoMethodError) { @controller.filter_parameters([{'password' => '[FILTERED]'}]) }
   end
 
-  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"')
-  end
-
   private
 
   def set_logger

actionpack/test/controller/logging_test.rb

-require 'abstract_unit'
-
-module Another
-  class LoggingController < ActionController::Base
-    layout "layouts/standard"
-
-    def show
-      render :nothing => true
-    end
-
-    def with_layout
-      render :template => "test/hello_world", :layout => true
-    end
-  end
-end
-
-class LoggingTest < ActionController::TestCase
-  tests Another::LoggingController
-
-  def setup
-    super
-    wait # Wait pending notifications to be published
-    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 4, logs.size
-    assert_nil logs.detect {|l| l =~ /Parameters/ }
-  end
-
-  def test_logging_with_parameters
-    get :show, :id => '10'
-    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
-    end
-
-    def logs
-      @logs ||= @controller.logger.logged
-    end
-end

actionpack/test/controller/subscriber_test.rb

+require "abstract_unit"
+require "rails/subscriber/test_helper"
+require "action_controller/railties/subscriber"
+
+module Another
+  class SubscribersController < ActionController::Base
+    def show
+      render :nothing => true
+    end
+
+    def redirector
+      redirect_to "http://foo.bar/"
+    end
+  end
+end
+
+module ActionControllerSubscriberTest
+  Rails::Subscriber.add(:action_controller, ActionController::Railties::Subscriber.new)
+
+  def self.included(base)
+    base.tests Another::SubscribersController
+  end
+
+  def wait
+    sleep(0.01)
+    super
+  end
+
+  def setup
+    @old_logger = ActionController::Base.logger
+    super
+  end
+
+  def teardown
+    super
+    ActionController::Base.logger = @old_logger
+  end
+
+  def set_logger(logger)
+    ActionController::Base.logger = logger
+  end
+
+  def test_process_action
+    get :show
+    wait
+    assert_equal 3, @logger.logged(:info).size
+    assert_match /Processed\sAnother::SubscribersController#show/, @logger.logged(:info)[0]
+  end
+
+  def test_process_action_without_parameters
+    get :show
+    wait
+    assert_nil @logger.logged(:info).detect {|l| l =~ /Parameters/ }
+  end
+
+  def test_process_action_with_parameters
+    get :show, :id => '10'
+    wait
+
+    assert_equal 4, @logger.logged(:info).size
+    assert_equal 'Parameters: {"id"=>"10"}', @logger.logged(:info)[1]
+  end
+
+  def test_process_action_with_view_runtime
+    get :show
+    wait
+    assert_match /View runtime/, @logger.logged(:info)[1]
+  end
+
+  def test_process_action_with_status_and_request_uri
+    get :show
+    wait
+    last = @logger.logged(:info).last
+    assert_match /Completed/, last
+    assert_match /200/, last
+    assert_match /another\/subscribers\/show/, last
+  end
+
+  def test_process_action_with_filter_parameters
+    Another::SubscribersController.filter_parameter_logging(:lifo, :amount)
+
+    get :show, :lifo => 'Pratik', :amount => '420', :step => '1'
+    wait
+
+    params = @logger.logged(:info)[1]
+    assert_match /"amount"=>"\[FILTERED\]"/, params
+    assert_match /"lifo"=>"\[FILTERED\]"/, params
+    assert_match /"step"=>"1"/, params
+  end
+
+  def test_redirect_to
+    get :redirector
+    wait
+
+    assert_equal 3, @logger.logged(:info).size
+    assert_equal "Redirected to http://foo.bar/ with status 302", @logger.logged(:info)[0]
+  end
+
+  class SyncSubscriberTest < ActionController::TestCase
+    include Rails::Subscriber::SyncTestHelper
+    include ActionControllerSubscriberTest
+  end
+
+  class AsyncSubscriberTest < ActionController::TestCase
+    include Rails::Subscriber::AsyncTestHelper
+    include ActionControllerSubscriberTest
+  end
+end

actionpack/test/template/subscriber_test.rb

+require "abstract_unit"
+require "rails/subscriber/test_helper"
+require "action_view/railties/subscriber"
+require "controller/fake_models"
+
+module ActionViewSubscriberTest
+  Rails::Subscriber.add(:action_view, ActionView::Railties::Subscriber.new)
+
+  def setup
+    @old_logger = ActionController::Base.logger
+    @view = ActionView::Base.new(ActionController::Base.view_paths, {})
+    Rails.stubs(:root).returns(File.expand_path(FIXTURE_LOAD_PATH))
+    super
+  end
+
+  def teardown
+    super
+    ActionController::Base.logger = @old_logger
+  end
+
+  def set_logger(logger)
+    ActionController::Base.logger = logger
+  end
+
+  def test_render_file_template
+    @view.render(:file => "test/hello_world.erb")
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /Rendered test\/hello_world\.erb/, @logger.logged(:info).last
+  end
+
+  def test_render_text_template
+    @view.render(:text => "OMG")
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /Rendered text template/, @logger.logged(:info).last
+  end
+
+  def test_render_inline_template
+    @view.render(:inline => "<%= 'OMG' %>")
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /Rendered inline template/, @logger.logged(:info).last
+  end
+
+  def test_render_partial_template
+    @view.render(:partial => "test/customer")
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /Rendered test\/_customer.erb/, @logger.logged(:info).last
+  end
+
+  def test_render_collection_template
+    @view.render(:partial => "test/customer", :collection => [ Customer.new("david"), Customer.new("mary") ])
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /Rendered test\/_customer.erb/, @logger.logged(:info).last
+  end
+
+  class SyncSubscriberTest < ActiveSupport::TestCase
+    include Rails::Subscriber::SyncTestHelper
+    include ActionViewSubscriberTest
+  end
+
+  class AsyncSubscriberTest < ActiveSupport::TestCase
+    include Rails::Subscriber::AsyncTestHelper
+    include ActionViewSubscriberTest
+  end
+end
\ No newline at end of file

activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb

@@ -14,7 +14,7 @@ def parse_sqlite_config!(config)
           # Allow database path relative to Rails.root, but only if
           # the database path is not the special path that tells
           # Sqlite to build a database only in memory.
-          if Object.const_defined?(:Rails) && ':memory:' != config[:database]
+          if defined?(Rails.root) && ':memory:' != config[:database]
             config[:database] = File.expand_path(config[:database], Rails.root)
           end
         end

activerecord/lib/active_record/railties/subscriber.rb

@@ -12,7 +12,7 @@ def sql(event)
           name = color(name, :magenta, true)
         end
 
-        debug "  #{name}  #{sql}"
+        debug "#{name}  #{sql}"
       end
 
       def odd?

activerecord/test/cases/subscriber_test.rb

@@ -6,7 +6,7 @@
 module SubscriberTest
   Rails::Subscriber.add(:active_record, ActiveRecord::Railties::Subscriber.new)
 
-  def super
+  def setup
     @old_logger = ActiveRecord::Base.logger
     super
   end
@@ -17,7 +17,7 @@ def teardown
   end
 
   def set_logger(logger)
-    ActiveRecord::Base.logger = @logger
+    ActiveRecord::Base.logger = logger
   end
 
   def test_basic_query_logging

activesupport/lib/active_support/deprecation/behaviors.rb

@@ -12,7 +12,7 @@ def behavior
       end
 
       def default_behavior
-        Deprecation::DEFAULT_BEHAVIORS[defined?(Rails) ? Rails.env.to_s : 'test']
+        Deprecation::DEFAULT_BEHAVIORS[defined?(Rails.env) ? Rails.env.to_s : 'test']
       end
     end
 

railties/lib/rails/subscriber/test_helper.rb

-require 'rails'
 require 'rails/subscriber'
+require 'active_support/notifications'
 
 module Rails
   class Subscriber
@@ -101,6 +101,11 @@ module AsyncTestHelper
       def queue
         ActiveSupport::Notifications::Fanout.new(false)
       end
+
+      def wait
+        sleep(0.01)
+        super
+      end
     end
   end
 end
\ No newline at end of file