Skip to content

Record the 401 of a Warden-halted request in the instrumentation payload - #5877

Open
sampokuokkanen wants to merge 2 commits into
heartcombo:mainfrom
sampokuokkanen:warden-status-in-instrumentation-payload
Open

sampokuokkanen wants to merge 2 commits into
heartcombo:mainfrom
sampokuokkanen:warden-status-in-instrumentation-payload

Conversation

@sampokuokkanen

Copy link
Copy Markdown

Rails main (8.2) logs request completion through the structured event reporter. ActionController::LogSubscriber#request_completed now gets a frozen event payload built from the instrumentation payload, and passes it to log_process_action. Devise's override writes payload[:status] ||= 401 into it, so every request halted by Warden raises:

FrozenError: can't modify frozen Hash: {controller: "ProfilesController", action: "show", db_runtime: 0.0, ...}
  devise/controllers/helpers.rb:84:in 'log_process_action'
  action_controller/log_subscriber.rb:25:in 'block in ActionController::LogSubscriber#request_completed'

The event reporter rescues it and reports it as a handled error, and the "Completed" line is never logged.

Fix

The status belongs in the instrumentation payload, not the log payload. This sets it in append_info_to_payload, which runs in the ensure of process_action while that payload is still open. Every subscriber then sees it: the log line, structured events, and APM tools.

This was tried in #4375 and reverted in #4804, because append_info_to_payload could not tell an exception from a Warden throw. That no longer applies. Since Rails 7.0, the lowest version Devise supports, process_action sets the status in its rescue before the ensure runs. A completed action and a raised exception both have a status by then, so a missing one means Warden threw. That is the case #4788 was about, and it is tested here.

Tests

New tests in AuthenticationInstrumentationTest:

The logging test fails on Rails main without this change, and passes with it on both Rails 8.1 and main. The full suite passes on the default Gemfile and on gemfiles/Gemfile-rails-main.

log_process_action wrote the status into the payload Rails logs from. Rails
8.2 logs from a frozen event payload, so that raised FrozenError and the
request was never logged. Set it in append_info_to_payload instead, where
the instrumentation payload is still open: every Rails Devise supports sets
the status of a completed or raised action before calling it, so a missing
status there means Warden threw.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

1 participant