Merge pull request rails#43755 from djfpaagman/log_route_redirects

Log redirects from router similarly to controller redirects

Author: byroot

actionpack/CHANGELOG.md

@@ -1,5 +1,8 @@
-*   Prevent `ActionDispatch::ServerTiming` from overwriting existing values in `Server-Timing`.
+*   Log redirects from routes the same way as redirects from controllers.
+
+    *Dennis Paagman*
 
+*   Prevent `ActionDispatch::ServerTiming` from overwriting existing values in `Server-Timing`.
     Previously, if another middleware down the chain set `Server-Timing` header,
     it would overwritten by `ActionDispatch::ServerTiming`.
 

actionpack/lib/action_dispatch/log_subscriber.rb

@@ -0,0 +1,22 @@
+# frozen_string_literal: true
+
+module ActionDispatch
+  class LogSubscriber < ActiveSupport::LogSubscriber
+    def redirect(event)
+      payload = event.payload
+
+      info { "Redirected to #{payload[:location]}" }
+
+      info do
+        status = payload[:status]
+
+        message = +"Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
+        message << "\n\n" if defined?(Rails.env) && Rails.env.development?
+
+        message
+      end
+    end
+  end
+end
+
+ActionDispatch::LogSubscriber.attach_to :action_dispatch

actionpack/lib/action_dispatch/railtie.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require "action_dispatch"
+require "action_dispatch/log_subscriber"
 require "active_support/messages/rotation_configuration"
 
 module ActionDispatch

actionpack/lib/action_dispatch/routing/redirection.rb

@@ -18,10 +18,17 @@ def initialize(status, block)
       def redirect?; true; end
 
       def call(env)
-        serve Request.new env
+        ActiveSupport::Notifications.instrument("redirect.action_dispatch") do |payload|
+          response = build_response(Request.new(env))
+
+          payload[:status] = @status
+          payload[:location] = response.headers["Location"]
+
+          response.to_a
+        end
       end
 
-      def serve(req)
+      def build_response(req)
         uri = URI.parse(path(req.path_parameters, req))
 
         unless uri.host
@@ -46,7 +53,7 @@ def serve(req)
           "Content-Length" => body.length.to_s
         }
 
-        [ status, headers, [body] ]
+        ActionDispatch::Response.new(status, headers, body)
       end
 
       def path(params, request)

actionpack/test/dispatch/routing/log_subscriber_test.rb

@@ -0,0 +1,39 @@
+# frozen_string_literal: true
+
+require "abstract_unit"
+require "active_support/log_subscriber/test_helper"
+require "action_dispatch/log_subscriber"
+
+class TestLogSubscriber < ActionDispatch::IntegrationTest
+  include ActiveSupport::LogSubscriber::TestHelper
+
+  def setup
+    super
+    ActionDispatch::LogSubscriber.attach_to :action_dispatch
+  end
+
+  def test_redirect_logging
+    draw do
+      get "redirect", to: redirect("/login")
+    end
+
+    get "/redirect"
+    wait
+    assert_equal 2, logs.size
+    assert_equal "Redirected to http://www.example.com/login", logs.first
+    assert_match(/Completed 301/, logs.last)
+  end
+
+private
+  def draw(&block)
+    self.class.stub_controllers do |routes|
+      routes.default_url_options = { host: "www.example.com" }
+      routes.draw(&block)
+      @app = RoutedRackApp.new routes
+    end
+  end
+
+  def logs
+    @logs ||= @logger.logged(:info)
+  end
+end