From c8350cc7233411c9811303b8700185b4bfba9b80 Mon Sep 17 00:00:00 2001 From: John Hawthorn Date: Wed, 16 Feb 2022 15:56:50 -0800 Subject: [PATCH] Use finish_with_state inside Rack::Logger This ensures that the finish instrumenter is sent to the same subscribers that the initial request was sent to. This solves an issue where in a threaded environment the dynamic subscriptions from ActionDispatch::ServerTiming would cause a mismatch in the number of subscriptions to a topic, which would pop too many values off of the thread-local stacks, leading to invalid events being sent to subscribers. Fixes #44167 --- railties/lib/rails/rack/logger.rb | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/railties/lib/rails/rack/logger.rb b/railties/lib/rails/rack/logger.rb index cfeae2f1df..a2518a052d 100644 --- a/railties/lib/rails/rack/logger.rb +++ b/railties/lib/rails/rack/logger.rb @@ -31,13 +31,17 @@ module Rails private def call_app(request, env) # :doc: instrumenter = ActiveSupport::Notifications.instrumenter - instrumenter.start "request.action_dispatch", request: request + instrumenter_state = instrumenter.start "request.action_dispatch", request: request + instrumenter_finish = -> () { + instrumenter.finish_with_state(instrumenter_state, "request.action_dispatch", request: request) + } + logger.info { started_request_message(request) } status, headers, body = @app.call(env) - body = ::Rack::BodyProxy.new(body) { finish(request) } + body = ::Rack::BodyProxy.new(body, &instrumenter_finish) [status, headers, body] rescue Exception - finish(request) + instrumenter_finish.call raise ensure ActiveSupport::LogSubscriber.flush_all! @@ -65,11 +69,6 @@ module Rails end end - def finish(request) - instrumenter = ActiveSupport::Notifications.instrumenter - instrumenter.finish "request.action_dispatch", request: request - end - def logger Rails.logger end