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

11 files changed, 208 insertions, 160 deletions

diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb
index 7222b7b2fa..876f778751 100644
--- a/actionpack/lib/action_controller/metal/instrumentation.rb
+++ b/actionpack/lib/action_controller/metal/instrumentation.rb
@@ -20,11 +20,7 @@ module ActionController
         result = super
         payload[:controller]  = self.class.name
         payload[:action]      = self.action_name
-        payload[:formats]     = request.formats.map(&:to_s)
-        payload[:remote_ip]   = request.remote_ip
-        payload[:method]      = request.method
         payload[:status]      = response.status
-        payload[:request_uri] = request.request_uri rescue "unknown"
         append_info_to_payload(payload)
         result
       end
diff --git a/actionpack/lib/action_controller/railtie.rb b/actionpack/lib/action_controller/railtie.rb
index d93155e7a5..7ea64c1923 100644
--- a/actionpack/lib/action_controller/railtie.rb
+++ b/actionpack/lib/action_controller/railtie.rb
@@ -39,53 +39,5 @@ module ActionController
       ActionController::Base.view_paths = view_path if ActionController::Base.view_paths.blank?
     end
 
-    class MetalMiddlewareBuilder
-      def initialize(metals)
-        @metals = metals
-      end
-
-      def new(app)
-        ActionDispatch::Cascade.new(@metals, app)
-      end
-
-      def name
-        ActionDispatch::Cascade.name
-      end
-      alias_method :to_s, :name
-    end
-
-    initializer "action_controller.initialize_metal" do |app|
-      metal_root = "#{Rails.root}/app/metal"
-      load_list = app.config.metals || Dir["#{metal_root}/**/*.rb"]
-
-      metals = load_list.map { |metal|
-        metal = File.basename(metal.gsub("#{metal_root}/", ''), '.rb')
-        require_dependency metal
-        metal.camelize.constantize
-      }.compact
-
-      middleware = MetalMiddlewareBuilder.new(metals)
-      app.config.middleware.insert_before(:"ActionDispatch::ParamsParser", middleware)
-    end
-
-    # Prepare dispatcher callbacks and run 'prepare' callbacks
-    initializer "action_controller.prepare_dispatcher" do |app|
-      # TODO: This used to say unless defined?(Dispatcher). Find out why and fix.
-      # Notice that at this point, ActionDispatch::Callbacks were already loaded.
-      require 'rails/dispatcher'
-
-      unless app.config.cache_classes
-        # Setup dev mode route reloading
-        routes_last_modified = app.routes_changed_at
-        reload_routes = lambda do
-          unless app.routes_changed_at == routes_last_modified
-            routes_last_modified = app.routes_changed_at
-            app.reload_routes!
-          end
-        end
-        ActionDispatch::Callbacks.before { |callbacks| reload_routes.call }
-      end
-    end
-
   end
 end
diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb
index a9f5d16c58..6659e5df47 100644
--- a/actionpack/lib/action_controller/railties/subscriber.rb
+++ b/actionpack/lib/action_controller/railties/subscriber.rb
@@ -3,18 +3,13 @@ module ActionController
     class Subscriber < Rails::Subscriber
       def process_action(event)
         payload = event.payload
-
-        info "\nProcessed #{payload[:controller]}##{payload[:action]} " \
-          "to #{payload[:formats].join(', ')} (for #{payload[:remote_ip]} at #{event.time.to_s(:db)}) " \
-          "[#{payload[:method].to_s.upcase}]"
-
         info "  Parameters: #{payload[:params].inspect}" unless payload[:params].blank?
 
         additions = ActionController::Base.log_process_action(payload)
 
         message = "Completed in %.0fms" % event.duration
         message << " (#{additions.join(" | ")})" unless additions.blank?
-        message << " | #{payload[:status]} [#{payload[:request_uri]}]\n\n"
+        message << " by #{payload[:controller]}##{payload[:action]} [#{payload[:status]}]"
 
         info(message)
       end
diff --git a/actionpack/lib/action_dispatch/railtie.rb b/actionpack/lib/action_dispatch/railtie.rb
new file mode 100644
index 0000000000..9fd034cdd2
--- /dev/null
+++ b/actionpack/lib/action_dispatch/railtie.rb
@@ -0,0 +1,58 @@
+require "action_dispatch"
+require "rails"
+
+module ActionDispatch
+  class Railtie < Rails::Railtie
+    plugin_name :action_dispatch
+
+    require "action_dispatch/railties/subscriber"
+    subscriber ActionDispatch::Railties::Subscriber.new
+
+    class MetalMiddlewareBuilder
+      def initialize(metals)
+        @metals = metals
+      end
+
+      def new(app)
+        ActionDispatch::Cascade.new(@metals, app)
+      end
+
+      def name
+        ActionDispatch::Cascade.name
+      end
+      alias_method :to_s, :name
+    end
+
+    initializer "action_dispatch.initialize_metal" do |app|
+      metal_root = "#{Rails.root}/app/metal"
+      load_list = app.config.metals || Dir["#{metal_root}/**/*.rb"]
+
+      metals = load_list.map { |metal|
+        metal = File.basename(metal.gsub("#{metal_root}/", ''), '.rb')
+        require_dependency metal
+        metal.camelize.constantize
+      }.compact
+
+      middleware = MetalMiddlewareBuilder.new(metals)
+      app.config.middleware.insert_before(:"ActionDispatch::ParamsParser", middleware)
+    end
+
+    # Prepare dispatcher callbacks and run 'prepare' callbacks
+    initializer "action_dispatch.prepare_dispatcher" do |app|
+      # TODO: This used to say unless defined?(Dispatcher). Find out why and fix.
+      require 'rails/dispatcher'
+
+      unless app.config.cache_classes
+        # Setup dev mode route reloading
+        routes_last_modified = app.routes_changed_at
+        reload_routes = lambda do
+          unless app.routes_changed_at == routes_last_modified
+            routes_last_modified = app.routes_changed_at
+            app.reload_routes!
+          end
+        end
+        ActionDispatch::Callbacks.before { |callbacks| reload_routes.call }
+      end
+    end
+  end
+end
\ No newline at end of file
diff --git a/actionpack/lib/action_dispatch/railties/subscriber.rb b/actionpack/lib/action_dispatch/railties/subscriber.rb
new file mode 100644
index 0000000000..c08a844c6a
--- /dev/null
+++ b/actionpack/lib/action_dispatch/railties/subscriber.rb
@@ -0,0 +1,17 @@
+module ActionDispatch
+  module Railties
+    class Subscriber < Rails::Subscriber
+      def before_dispatch(event)
+        request = Request.new(event.payload[:env])
+        path    = request.request_uri.inspect rescue "unknown"
+
+        info "\n\nProcessing #{path} to #{request.formats.join(', ')} " <<
+             "(for #{request.remote_ip} at #{event.time.to_s(:db)}) [#{request.method.to_s.upcase}]"
+      end
+
+      def logger
+        ActionController::Base.logger
+      end
+    end
+  end
+end
\ No newline at end of file
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
diff --git a/activerecord/lib/active_record/railties/subscriber.rb b/activerecord/lib/active_record/railties/subscriber.rb
index 7c2a10cf0f..fd873dbff8 100644
--- a/activerecord/lib/active_record/railties/subscriber.rb
+++ b/activerecord/lib/active_record/railties/subscriber.rb
@@ -12,7 +12,7 @@ module ActiveRecord
           name = color(name, :magenta, true)
         end
 
-        debug "#{name}  #{sql}"
+        debug "  #{name}  #{sql}"
       end
 
       def odd?
diff --git a/railties/lib/rails.rb b/railties/lib/rails.rb
index 4ded2515fc..0bc7160815 100644
--- a/railties/lib/rails.rb
+++ b/railties/lib/rails.rb
@@ -1,9 +1,8 @@
-require "pathname"
+require 'pathname'
 
 require 'active_support'
 require 'active_support/core_ext/kernel/reporting'
 require 'active_support/core_ext/logger'
-require 'action_dispatch'
 
 require 'rails/initializable'
 require 'rails/application'
@@ -18,6 +17,8 @@ require 'rails/deprecation'
 require 'rails/subscriber'
 require 'rails/ruby_version_check'
 
+require 'action_dispatch/railtie'
+
 # For Ruby 1.8, this initialization sets $KCODE to 'u' to enable the
 # multibyte safe operations. Plugin authors supporting other encodings
 # should override this behaviour and set the relevant +default_charset+