Add subscriber for ActionPack and move all logging inside it.

6 files changed, 182 insertions, 133 deletions

diff --git a/actionpack/test/abstract_unit.rb b/actionpack/test/abstract_unit.rb
index 3f7a5c89b9..3e631d45df 100644
--- a/actionpack/test/abstract_unit.rb
+++ b/actionpack/test/abstract_unit.rb
@@ -48,14 +48,6 @@ ORIGINAL_LOCALES = I18n.available_locales.map {|locale| locale.to_s }.sort
 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|
diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb
index 5a8dc0c358..8a13d1e5f1 100644
--- a/actionpack/test/controller/caching_test.rb
+++ b/actionpack/test/controller/caching_test.rb
@@ -629,20 +629,6 @@ class FragmentCachingTest < ActionController::TestCase
     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
diff --git a/actionpack/test/controller/filter_params_test.rb b/actionpack/test/controller/filter_params_test.rb
index 420ebeacf4..d0635669c2 100644
--- a/actionpack/test/controller/filter_params_test.rb
+++ b/actionpack/test/controller/filter_params_test.rb
@@ -66,18 +66,6 @@ class FilterParamTest < ActionController::TestCase
     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
diff --git a/actionpack/test/controller/logging_test.rb b/actionpack/test/controller/logging_test.rb
deleted file mode 100644
index 594cf17312..0000000000
--- a/actionpack/test/controller/logging_test.rb
+++ /dev/null
@@ -1,81 +0,0 @@
-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
diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb
new file mode 100644
index 0000000000..e2c6150c5e
--- /dev/null
+++ b/actionpack/test/controller/subscriber_test.rb
@@ -0,0 +1,108 @@
+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
diff --git a/actionpack/test/template/subscriber_test.rb b/actionpack/test/template/subscriber_test.rb
new file mode 100644
index 0000000000..a73ff2e932
--- /dev/null
+++ b/actionpack/test/template/subscriber_test.rb
@@ -0,0 +1,74 @@
+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