Merge pull request rails#50573 from KJTsanaktsidis/ktsanaktsidis/delay_flushing_rack_logger

Ensure that LogSubscriber.flush_all! is called after LogSubscribers run

Author: rafaelfranca

railties/lib/rails/rack/logger.rb

@@ -35,7 +35,7 @@ def call_app(request, env) # :doc:
 
           logger.info { started_request_message(request) }
           status, headers, body = response = @app.call(env)
-          body = ::Rack::BodyProxy.new(body, &handle.method(:finish))
+          body = ::Rack::BodyProxy.new(body) { finish_request_instrumentation(handle) }
 
           if response.frozen?
             [status, headers, body]
@@ -44,10 +44,8 @@ def call_app(request, env) # :doc:
             response
           end
         rescue Exception
-          handle.finish
+          finish_request_instrumentation(handle)
           raise
-        ensure
-          ActiveSupport::LogSubscriber.flush_all!
         end
 
         # Started GET "/session/new" for 127.0.0.1 at 2012-09-26 14:51:42 -0700
@@ -75,6 +73,11 @@ def compute_tags(request) # :doc:
         def logger
           Rails.logger
         end
+
+        def finish_request_instrumentation(handle)
+          handle.finish
+          ActiveSupport::LogSubscriber.flush_all!
+        end
     end
   end
 end

railties/test/rack_logger_test.rb

@@ -5,10 +5,13 @@
 require "active_support/test_case"
 require "rails/rack/logger"
 require "logger"
+require "active_support/log_subscriber/test_helper"
 
 module Rails
   module Rack
     class LoggerTest < ActiveSupport::TestCase
+      include ActiveSupport::LogSubscriber::TestHelper
+
       class TestLogger < Rails::Rack::Logger
         NULL = ::Logger.new File::NULL
 
@@ -43,16 +46,16 @@ def finish(name, id, payload)
         end
       end
 
-      attr_reader :subscriber, :notifier
+      attr_reader :subscriber
 
       def setup
+        super
         @subscriber = Subscriber.new
-        @notifier = ActiveSupport::Notifications.notifier
-        @subscription = notifier.subscribe "request.action_dispatch", subscriber
+        @subscription = ActiveSupport::Notifications.notifier.subscribe "request.action_dispatch", subscriber
       end
 
       def teardown
-        notifier.unsubscribe @subscription
+        ActiveSupport::Notifications.notifier.unsubscribe @subscription
       end
 
       def test_notification
@@ -90,6 +93,32 @@ def test_logger_does_not_mutate_app_return
           end
         end
       end
+
+      def test_logger_is_flushed_after_request_finished
+        logger_middleware = TestLogger.new { }
+
+        flush_count_in_request_event = nil
+        block_sub = @notifier.subscribe "request.action_dispatch" do |_event|
+          flush_count_in_request_event = ActiveSupport::LogSubscriber.logger.flush_count
+        end
+
+        # Assert that we don't get a logger flush when we finish the response headers
+        response_body = nil
+        assert_no_difference("ActiveSupport::LogSubscriber.logger.flush_count") do
+          response_body = logger_middleware.call("REQUEST_METHOD" => "GET").last
+        end
+
+        # Assert that we _do_ get a logger flush when we finish the response body
+        assert_difference("ActiveSupport::LogSubscriber.logger.flush_count") do
+          response_body.close
+        end
+
+        # And that the flush happens _after_ any LogSubscribers etc get run.
+        flush_count = ActiveSupport::LogSubscriber.logger.flush_count
+        assert_equal(1, flush_count - flush_count_in_request_event, "flush_all! should happen after event")
+      ensure
+        @notifier.unsubscribe block_sub
+      end
     end
   end
 end