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
This commit is contained in:
John Hawthorn 2022-02-16 15:56:50 -08:00
parent 0dbe699d5c
commit c8350cc723
1 changed files with 7 additions and 8 deletions

View File

@ -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