At the moment, Rails::Rack::Logger tags the logger (if it's
ActiveSupport::TaggedLogging) for the duration of the @app.call, but
only fires the request.action_dispatch event later, on body close. That
means anything logged in request.action_dispatch handlers won't have the
same tags as the rest of the request.
Fix this by deferring the popping of tags into
finish_request_instrumentation, in the same way that finishing the
instrumentation handle is deferred.
The Rails::Rack::Logger middleware defers finishing the
request.action_dispatch notification until the body is written. However,
it calls ActiveSupport::LogSubscriber.flush_all! immediately once the
headers are written, before the body is closed.
This means that if you have a custom ActiveSupport::LogSubscriber
attached to request.action_dispatch, any logs you write there are NOT
flushed until the _next_ request finishes (or something else calls
Rails.logger.flush or some such).
Currently test `#test_logger_does_not_mutate_app_return` doesn't
test mutation of response and the test passes with and without changes
added in #32444. `#freeze` response in the test in order to
test mutation.
If @app.call returns an object that is saved (for e.g., in a constant), the mutation results in a continuing cycle of wrapping the body in Rack::BodyProxy, eventually leading to SystemStackError
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
On branch fix-return-response-mutation-rack-logger - Tue 3 Apr 2018 19:54:28 PDT by Geoff Lee <geoff.lee@lendesk.com>
