Default to sync instrumentation.

8 files changed, 61 insertions, 81 deletions

diff --git a/railties/lib/rails/commands/server.rb b/railties/lib/rails/commands/server.rb
index 115499db05..b21ae2a17b 100644
--- a/railties/lib/rails/commands/server.rb
+++ b/railties/lib/rails/commands/server.rb
@@ -46,7 +46,6 @@ module Rails
       trap(:INT) { exit }
       puts "=> Ctrl-C to shutdown server" unless options[:daemonize]
 
-      initialize_log_tailer! unless options[:daemonize]
       super
     ensure
       puts 'Exiting' unless options[:daemonize]
@@ -54,6 +53,7 @@ module Rails
 
     def middleware
       middlewares = []
+      middlewares << [Rails::Rack::LogTailer, log_path] unless options[:daemonize]
       middlewares << [Rails::Rack::Debugger]  if options[:debugger]
       Hash.new(middlewares)
     end
@@ -71,14 +71,5 @@ module Rails
         :pid         => "tmp/pids/server.pid"
       })
     end
-
-  protected
-
-    # LogTailer should not be used as a middleware since the logging happens
-    # async in a request and the middleware calls are sync. So we send it
-    # to subscriber which will be responsible for calling tail! in the log tailer.
-    def initialize_log_tailer!
-      Rails::Subscriber.log_tailer = Rails::Rack::LogTailer.new(nil, log_path)
-    end
   end
 end
diff --git a/railties/lib/rails/configuration.rb b/railties/lib/rails/configuration.rb
index a9586b6e9e..c7331f79c5 100644
--- a/railties/lib/rails/configuration.rb
+++ b/railties/lib/rails/configuration.rb
@@ -10,15 +10,15 @@ module Rails
 
     def self.default_middleware_stack
       ActionDispatch::MiddlewareStack.new.tap do |middleware|
-        middleware.use('ActionDispatch::Static', lambda { Rails.public_path }, :if => lambda { Rails.application.config.serve_static_assets })
+        middleware.use('::ActionDispatch::Static', lambda { Rails.public_path }, :if => lambda { Rails.application.config.serve_static_assets })
         middleware.use('::Rack::Lock', :if => lambda { !ActionController::Base.allow_concurrency })
         middleware.use('::Rack::Runtime')
-        middleware.use('ActionDispatch::ShowExceptions', lambda { ActionController::Base.consider_all_requests_local })
-        middleware.use('ActionDispatch::Notifications')
-        middleware.use('ActionDispatch::Callbacks', lambda { !Rails.application.config.cache_classes })
-        middleware.use('ActionDispatch::Cookies')
+        middleware.use('::Rails::Rack::Logger')
+        middleware.use('::ActionDispatch::ShowExceptions', lambda { ActionController::Base.consider_all_requests_local })
+        middleware.use('::ActionDispatch::Callbacks', lambda { !Rails.application.config.cache_classes })
+        middleware.use('::ActionDispatch::Cookies')
         middleware.use(lambda { ActionController::Base.session_store }, lambda { ActionController::Base.session_options })
-        middleware.use('ActionDispatch::Flash', :if => lambda { ActionController::Base.session_store })
+        middleware.use('::ActionDispatch::Flash', :if => lambda { ActionController::Base.session_store })
         middleware.use(lambda { Rails::Rack::Metal.new(Rails.application.config.paths.app.metals.to_a, Rails.application.config.metals) })
         middleware.use('ActionDispatch::ParamsParser')
         middleware.use('::Rack::MethodOverride')
diff --git a/railties/lib/rails/rack.rb b/railties/lib/rails/rack.rb
index 36945a6b0f..4bc0c2c88b 100644
--- a/railties/lib/rails/rack.rb
+++ b/railties/lib/rails/rack.rb
@@ -1,6 +1,7 @@
 module Rails
   module Rack
     autoload :Debugger,  "rails/rack/debugger"
+    autoload :Logger,    "rails/rack/logger"
     autoload :LogTailer, "rails/rack/log_tailer"
     autoload :Metal,     "rails/rack/metal"
     autoload :Static,    "rails/rack/static"
diff --git a/railties/lib/rails/rack/logger.rb b/railties/lib/rails/rack/logger.rb
new file mode 100644
index 0000000000..91a613092f
--- /dev/null
+++ b/railties/lib/rails/rack/logger.rb
@@ -0,0 +1,38 @@
+require 'rails/subscriber'
+
+module Rails
+  module Rack
+    # Log the request started and flush all loggers after it.
+    class Logger < Rails::Subscriber
+      def initialize(app)
+        @app = app
+      end
+
+      def call(env)
+        @env = env
+        before_dispatch
+        result = @app.call(@env)
+        after_dispatch
+        result
+      end
+
+      protected
+
+        def request
+          @request ||= ActionDispatch::Request.new(@env) 
+        end
+
+        def before_dispatch
+          path = request.request_uri.inspect rescue "unknown"
+
+          info "\n\nStarted #{request.method.to_s.upcase} #{path} " <<
+                      "for #{request.remote_ip} at #{Time.now.to_s(:db)}"
+        end
+
+        def after_dispatch
+          Rails::Subscriber.flush_all!
+        end
+
+    end
+  end
+end
diff --git a/railties/lib/rails/subscriber.rb b/railties/lib/rails/subscriber.rb
index 9965786d86..8c62f562d9 100644
--- a/railties/lib/rails/subscriber.rb
+++ b/railties/lib/rails/subscriber.rb
@@ -33,7 +33,7 @@ module Rails
   # Subscriber also has some helpers to deal with logging and automatically flushes
   # all logs when the request finishes (via action_dispatch.callback notification).
   class Subscriber
-    mattr_accessor :colorize_logging, :log_tailer
+    mattr_accessor :colorize_logging
     self.colorize_logging = true
 
     # Embed in a String to clear all previous ANSI sequences.
@@ -69,11 +69,6 @@ module Rails
           Rails.logger.error "Could not log #{args[0].inspect} event. #{e.class}: #{e.message}"
         end
       end
-
-      if args[0] == "action_dispatch.after_dispatch" && !subscribers.empty?
-        flush_all!
-        log_tailer.tail! if log_tailer
-      end
     end
 
     # Flush all subscribers' logger.
diff --git a/railties/lib/rails/subscriber/test_helper.rb b/railties/lib/rails/subscriber/test_helper.rb
index 1464767ed9..39b4117372 100644
--- a/railties/lib/rails/subscriber/test_helper.rb
+++ b/railties/lib/rails/subscriber/test_helper.rb
@@ -1,12 +1,12 @@
 require 'rails/subscriber'
-require 'active_support/notifications'
 
 module Rails
   class Subscriber
     # Provides some helpers to deal with testing subscribers by setting up
     # notifications. Take for instance ActiveRecord subscriber tests:
     #
-    #   module SubscriberTest
+    #   class SyncSubscriberTest < ActiveSupport::TestCase
+    #     include Rails::Subscriber::TestHelper
     #     Rails::Subscriber.add(:active_record, ActiveRecord::Railties::Subscriber.new)
     # 
     #     def test_basic_query_logging
@@ -39,8 +39,6 @@ module Rails
     #
     module TestHelper
       def setup
-        Thread.abort_on_exception = true
-
         @logger   = MockLogger.new
         @notifier = ActiveSupport::Notifications::Notifier.new(queue)
 
@@ -54,7 +52,6 @@ module Rails
       def teardown
         set_logger(nil)
         ActiveSupport::Notifications.notifier = nil
-        Thread.abort_on_exception = false
       end
 
       class MockLogger
@@ -92,26 +89,9 @@ module Rails
       def set_logger(logger)
         Rails.logger = logger
       end
-    end
-    
-    module SyncTestHelper
-      include TestHelper
-
-      def queue
-        ActiveSupport::Notifications::Fanout.new(true)
-      end
-    end
-
-    module AsyncTestHelper
-      include TestHelper
 
       def queue
-        ActiveSupport::Notifications::Fanout.new(false)
-      end
-
-      def wait
-        sleep(0.01)
-        super
+        ActiveSupport::Notifications::Fanout.new
       end
     end
   end
diff --git a/railties/test/application/middleware_test.rb b/railties/test/application/middleware_test.rb
index 1c5cc62ecd..8c4247e840 100644
--- a/railties/test/application/middleware_test.rb
+++ b/railties/test/application/middleware_test.rb
@@ -17,8 +17,8 @@ module ApplicationTests
         "ActionDispatch::Static",
         "Rack::Lock",
         "Rack::Runtime",
+        "Rails::Rack::Logger",
         "ActionDispatch::ShowExceptions",
-        "ActionDispatch::Notifications",
         "ActionDispatch::Callbacks",
         "ActionDispatch::Cookies",
         "ActionDispatch::Session::CookieStore",
diff --git a/railties/test/subscriber_test.rb b/railties/test/subscriber_test.rb
index 724e8a75d6..f6c895093f 100644
--- a/railties/test/subscriber_test.rb
+++ b/railties/test/subscriber_test.rb
@@ -24,7 +24,9 @@ class MySubscriber < Rails::Subscriber
   end
 end
 
-module SubscriberTest
+class SyncSubscriberTest < ActiveSupport::TestCase
+  include Rails::Subscriber::TestHelper
+
   def setup
     super
     @subscriber = MySubscriber.new
@@ -94,51 +96,24 @@ module SubscriberTest
     assert_equal 1, @logger.flush_count
   end
 
-  def test_flushes_loggers_when_action_dispatch_callback_is_received
-    Rails::Subscriber.add :my_subscriber, @subscriber
-    instrument "action_dispatch.after_dispatch"
-    wait
-    assert_equal 1, @logger.flush_count
-  end
-
   def test_flushes_the_same_logger_just_once
     Rails::Subscriber.add :my_subscriber, @subscriber
     Rails::Subscriber.add :another, @subscriber
-    instrument "action_dispatch.after_dispatch"
+    Rails::Subscriber.flush_all!
     wait
     assert_equal 1, @logger.flush_count
   end
 
-  def test_logging_thread_does_not_die_on_failures
+  def test_logging_does_not_die_on_failures
     Rails::Subscriber.add :my_subscriber, @subscriber
     instrument "my_subscriber.puke"
-    instrument "action_dispatch.after_dispatch"
-    wait
-    assert_equal 1, @logger.flush_count
-    assert_equal 1, @logger.logged(:error).size
-    assert_equal 'Could not log "my_subscriber.puke" event. RuntimeError: puke', @logger.logged(:error).last
-  end
-
-  def test_tails_logs_when_action_dispatch_callback_is_received
-    log_tailer = mock()
-    log_tailer.expects(:tail!)
-    Rails::Subscriber.log_tailer = log_tailer
-
-    Rails::Subscriber.add :my_subscriber, @subscriber
-    instrument "action_dispatch.after_dispatch"
+    instrument "my_subscriber.some_event"
     wait
-  ensure
-    Rails::Subscriber.log_tailer = nil
-  end
 
-  class SyncSubscriberTest < ActiveSupport::TestCase
-    include Rails::Subscriber::SyncTestHelper
-    include SubscriberTest
-  end
+    assert_equal 1, @logger.logged(:info).size
+    assert_equal 'my_subscriber.some_event', @logger.logged(:info).last
 
-  class AsyncSubscriberTest < ActiveSupport::TestCase
-    include Rails::Subscriber::AsyncTestHelper
-    include SubscriberTest
+    assert_equal 1, @logger.logged(:error).size
+    assert_equal 'Could not log "my_subscriber.puke" event. RuntimeError: puke', @logger.logged(:error).last
   end
-
 end
\ No newline at end of file