Add ActionDispatch::Railties::Subscriber and finish tidying up the logging.

4 files changed, 128 insertions, 99 deletions

diff --git a/actionpack/test/activerecord/controller_runtime_test.rb b/actionpack/test/activerecord/controller_runtime_test.rb
index 37c7738301..d6f7cd80ab 100644
--- a/actionpack/test/activerecord/controller_runtime_test.rb
+++ b/actionpack/test/activerecord/controller_runtime_test.rb
@@ -37,8 +37,8 @@ module ControllerRuntimeSubscriberTest
     get :show
     wait
 
-    assert_equal 2, @logger.logged(:info).size
-    assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[1]
+    assert_equal 1, @logger.logged(:info).size
+    assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[0]
   end
 
   class SyncSubscriberTest < ActionController::TestCase
diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb
index ef1a325799..24132ee928 100644
--- a/actionpack/test/controller/subscriber_test.rb
+++ b/actionpack/test/controller/subscriber_test.rb
@@ -66,15 +66,10 @@ module ActionControllerSubscriberTest
   def test_process_action
     get :show
     wait
-    assert_equal 2, logs.size
-    assert_match /Processed\sAnother::SubscribersController#show/, logs[0]
-  end
-
-  def test_process_action_formats
-    get :show
-    wait
-    assert_equal 2, logs.size
-    assert_match /text\/html/, logs[0]
+    assert_equal 1, logs.size
+    assert_match /Completed/, logs.first
+    assert_match /\[200\]/, logs.first
+    assert_match /Another::SubscribersController#show/, logs.first
   end
 
   def test_process_action_without_parameters
@@ -87,23 +82,14 @@ module ActionControllerSubscriberTest
     get :show, :id => '10'
     wait
 
-    assert_equal 3, logs.size
-    assert_equal 'Parameters: {"id"=>"10"}', logs[1]
+    assert_equal 2, logs.size
+    assert_equal 'Parameters: {"id"=>"10"}', logs[0]
   end
 
   def test_process_action_with_view_runtime
     get :show
     wait
-    assert_match /\(Views: [\d\.]+ms\)/, logs[1]
-  end
-
-  def test_process_action_with_status_and_request_uri
-    get :show
-    wait
-    last = logs.last
-    assert_match /Completed/, last
-    assert_match /200/, last
-    assert_match /another\/subscribers\/show/, last
+    assert_match /\(Views: [\d\.]+ms\)/, logs[0]
   end
 
   def test_process_action_with_filter_parameters
@@ -112,7 +98,7 @@ module ActionControllerSubscriberTest
     get :show, :lifo => 'Pratik', :amount => '420', :step => '1'
     wait
 
-    params = logs[1]
+    params = logs[0]
     assert_match /"amount"=>"\[FILTERED\]"/, params
     assert_match /"lifo"=>"\[FILTERED\]"/, params
     assert_match /"step"=>"1"/, params
@@ -122,7 +108,7 @@ module ActionControllerSubscriberTest
     get :redirector
     wait
 
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_equal "Redirected to http://foo.bar/", logs[0]
   end
 
@@ -130,7 +116,7 @@ module ActionControllerSubscriberTest
     get :data_sender
     wait
 
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_match /Sent data omg\.txt/, logs[0]
   end
 
@@ -138,7 +124,7 @@ module ActionControllerSubscriberTest
     get :file_sender
     wait
 
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_match /Sent file/, logs[0]
     assert_match /test\/fixtures\/company\.rb/, logs[0]
   end
@@ -147,7 +133,7 @@ module ActionControllerSubscriberTest
     get :xfile_sender
     wait
 
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_match /Sent X\-Sendfile header/, logs[0]
     assert_match /test\/fixtures\/company\.rb/, logs[0]
   end
@@ -157,7 +143,7 @@ module ActionControllerSubscriberTest
     get :with_fragment_cache
     wait
 
-    assert_equal 4, logs.size
+    assert_equal 3, logs.size
     assert_match /Exist fragment\? views\/foo/, logs[0]
     assert_match /Write fragment views\/foo/, logs[1]
   ensure
@@ -169,7 +155,7 @@ module ActionControllerSubscriberTest
     get :with_page_cache
     wait
 
-    assert_equal 3, logs.size
+    assert_equal 2, logs.size
     assert_match /Write page/, logs[0]
     assert_match /\/index\.html/, logs[0]
   ensure
diff --git a/actionpack/test/dispatch/notifications_test.rb b/actionpack/test/dispatch/notifications_test.rb
deleted file mode 100644
index d834a734ef..0000000000
--- a/actionpack/test/dispatch/notifications_test.rb
+++ /dev/null
@@ -1,69 +0,0 @@
-require 'abstract_unit'
-
-class NotificationsMiddlewareTest < ActionController::IntegrationTest
-  Boomer = lambda do |env|
-    req = ActionDispatch::Request.new(env)
-    case req.path
-    when "/"
-      [200, {}, []]
-    else
-      raise "puke!"
-    end
-  end
-
-  App = ActionDispatch::Notifications.new(Boomer)
-
-  def setup
-    @queue    = ActiveSupport::Notifications::Fanout.new
-    @notifier = ActiveSupport::Notifications::Notifier.new(@queue)
-    ActiveSupport::Notifications.notifier = @notifier
-
-    @events = []
-    ActiveSupport::Notifications.subscribe do |*args|
-      @events << args
-    end
-
-    @app = App
-  end
-
-  test "publishes notifications" do
-    get "/"
-    ActiveSupport::Notifications.notifier.wait
-
-    assert_equal 2, @events.size
-    before, after = @events
-
-    assert_equal 'action_dispatch.before_dispatch', before[0]
-    assert_kind_of Hash, before[4][:env]
-    assert_equal 'GET',  before[4][:env]["REQUEST_METHOD"]
-
-    assert_equal 'action_dispatch.after_dispatch', after[0]
-    assert_kind_of Hash, after[4][:env]
-    assert_equal 'GET',  after[4][:env]["REQUEST_METHOD"]
-  end
-
-  test "publishes notifications on failure" do
-    begin
-      get "/puke"
-    rescue
-    end
-
-    ActiveSupport::Notifications.notifier.wait
-
-    assert_equal 3, @events.size
-    before, after, exception = @events
-
-    assert_equal 'action_dispatch.before_dispatch', before[0]
-    assert_kind_of Hash, before[4][:env]
-    assert_equal 'GET',  before[4][:env]["REQUEST_METHOD"]
-
-    assert_equal 'action_dispatch.after_dispatch', after[0]
-    assert_kind_of Hash, after[4][:env]
-    assert_equal 'GET',  after[4][:env]["REQUEST_METHOD"]  
-
-    assert_equal 'action_dispatch.exception', exception[0]
-    assert_kind_of Hash, exception[4][:env]
-    assert_equal 'GET',  exception[4][:env]["REQUEST_METHOD"]  
-    assert_kind_of RuntimeError, exception[4][:exception]
-  end
-end
\ No newline at end of file
diff --git a/actionpack/test/dispatch/subscriber_test.rb b/actionpack/test/dispatch/subscriber_test.rb
new file mode 100644
index 0000000000..a7f1a2659a
--- /dev/null
+++ b/actionpack/test/dispatch/subscriber_test.rb
@@ -0,0 +1,112 @@
+require "abstract_unit"
+require "rails/subscriber/test_helper"
+require "action_dispatch/railties/subscriber"
+
+module DispatcherSubscriberTest
+  Boomer = lambda do |env|
+    req = ActionDispatch::Request.new(env)
+    case req.path
+    when "/"
+      [200, {}, []]
+    else
+      raise "puke!"
+    end
+  end
+
+  App = ActionDispatch::Notifications.new(Boomer)
+
+  def setup
+    Rails::Subscriber.add(:action_dispatch, ActionDispatch::Railties::Subscriber.new)
+    @app = App
+    super
+
+    @events = []
+    ActiveSupport::Notifications.subscribe do |*args|
+      @events << args
+    end
+  end
+
+  def set_logger(logger)
+    ActionController::Base.logger = logger
+  end
+
+  def test_publishes_notifications
+    get "/"
+    wait
+
+    assert_equal 2, @events.size
+    before, after = @events
+
+    assert_equal 'action_dispatch.before_dispatch', before[0]
+    assert_kind_of Hash, before[4][:env]
+    assert_equal 'GET',  before[4][:env]["REQUEST_METHOD"]
+
+    assert_equal 'action_dispatch.after_dispatch', after[0]
+    assert_kind_of Hash, after[4][:env]
+    assert_equal 'GET',  after[4][:env]["REQUEST_METHOD"]
+  end
+
+  def test_publishes_notifications_even_on_failures
+    begin
+      get "/puke"
+    rescue
+    end
+
+    wait
+
+    assert_equal 3, @events.size
+    before, after, exception = @events
+
+    assert_equal 'action_dispatch.before_dispatch', before[0]
+    assert_kind_of Hash, before[4][:env]
+    assert_equal 'GET',  before[4][:env]["REQUEST_METHOD"]
+
+    assert_equal 'action_dispatch.after_dispatch', after[0]
+    assert_kind_of Hash, after[4][:env]
+    assert_equal 'GET',  after[4][:env]["REQUEST_METHOD"]
+
+    assert_equal 'action_dispatch.exception', exception[0]
+    assert_kind_of Hash, exception[4][:env]
+    assert_equal 'GET',  exception[4][:env]["REQUEST_METHOD"]
+    assert_kind_of RuntimeError, exception[4][:exception]
+  end
+
+  def test_subscriber_logs_notifications
+    get "/"
+    wait
+
+    log = @logger.logged(:info).first
+    assert_equal 1, @logger.logged(:info).size
+
+    assert_match %r{^Processing "/" to text/html}, log
+    assert_match %r{\(for 127\.0\.0\.1}, log
+    assert_match %r{\[GET\]}, log
+  end
+
+  def test_subscriber_has_its_logged_flushed_after_request
+    assert_equal 0, @logger.flush_count
+    get "/"
+    wait
+    assert_equal 1, @logger.flush_count
+  end
+
+  def test_subscriber_has_its_logged_flushed_even_after_busted_requests
+    assert_equal 0, @logger.flush_count
+    begin
+      get "/puke"
+    rescue
+    end
+    wait
+    assert_equal 1, @logger.flush_count
+  end
+
+  class SyncSubscriberTest < ActionController::IntegrationTest
+    include Rails::Subscriber::SyncTestHelper
+    include DispatcherSubscriberTest
+  end
+
+  class AsyncSubscriberTest < ActionController::IntegrationTest
+    include Rails::Subscriber::AsyncTestHelper
+    include DispatcherSubscriberTest
+  end
+end
\ No newline at end of file