Request start log messages should use ActiveSupport::LogSubscriber in Rails::Rack::Logger

rubyonrails-core
,
1

Currently the following log message

Started GET "/something" for 127.0.0.1 at 2023-07-14 09:52:04 +0200"

is directly logged in Rails::Rack::Logger using Rails.logger.info in railties/lib/rails/rack/logger.rb

This poses a problem when you want to switch to structured logs (JSON), logging libraries like SemanticLogger and LogRage override this class because of this. There is currently no way of preventing or modifying this log message without patching Rails::Rack::Logger.

I’d like to propose that we should use ActiveSupport::LogSubscriber for this with an Evented LogSubscriber, this can be done by extending actionpack/lib/action_dispatch/log_subscriber.rb with something like:

module ActionDispatch
  class LogSubscriber < ActiveSupport::LogSubscriber
     # existing code ...

     def self.attach_to(*)
       ActiveSupport::Notifications.subscribe('request.action_dispatch', Request.new)

       super
     end

     class Request
       def start(name, _id, payload)
         return unless logger&.info?

         request = payload[:request]

         logger.info(
           sprintf(
             'Started %s "%s" for %s at %s',
              request.raw_request_method,
              request.filtered_path,
              request.remote_ip,
              Time.now
           )
         )
       end

       def finish(_name, _id, _payload); end

       def logger
         Rails.logger
       end
    end
  end
end

A similar approach is used in ActionView’s log subscriber in actionview/lib/action_view/log_subscriber.rb

If you support this change I can contribute the change with tests.