No status code in Rails log after Warden auth failure

Question

I've set up a Rails 5 (5.0.0.rc1) app with the --api flag. It's using Warden for authentication.

It all works, except that when Warden authentication fails, the response isn't being logged properly. The log looks like this:

Started GET "/widgets.json" for ::1 at 2016-06-14 11:38:20 +0000
Processing by WidgetsController#index as JSON
Completed   in 0ms (ActiveRecord: 0.0ms)

or, in production:

I, [2016-06-14T14:12:54.938271 #17625]  INFO -- : [db39f895-eeb1-4861-91d0-5d52c124e37a] Completed   in 1ms (ActiveRecord: 0.0ms)

It should of course be saying Completed 401 Unauthorized in..., but for whatever reason, it doesn't know the status code of the response.

Warden authentication errors are being sent to a Rack compatible, ActionController::Metal-derived controller that's very simple:

class UnauthorizedController < ActionController::Metal
  include ActionController::Head

  def self.call(env)
    @respond ||= action(:respond)
    @respond.call(env)
  end

  def respond
    head :unauthorized
  end
end

It's using the basic head method to respond (no need to render anything), so presumably it'd behave the same as using head in a regular Rails controller. But no.

Same thing happens if I try using redirect_to ... or render ... (after including the relevant modules). So somewhere in the Rack → Rails → Warden → Warden failure app (controller) the status code of the response goes missing. The log knows to start logging the request, and knows that it's been handled, since it obviously spits out the "Completed..."-line. But something's not hooked up right.

Any ideas on how to fix this?

Answer 1

Warden doesn't have a rails logger. It just throws an exception and catch it, Warden provides a way to handle this exception by before_failure callback

# config/inializers/warden_config.rb
Warden::Manager.before_failure do |env, opts|
  Rails.logger.info("401 Unuthorized")
end

Answer 2

I think you're running into something similar to https://github.com/roidrage/lograge/issues/67#issuecomment-601604344. This may be a limitation with how the Rails log instrumentation works. I think the controller finishes processing the event, which then causes Rails to print the log message with a nil status code. But then the Warden middleware swoops in and sets the right response code. You could add include ActionController::Instrumentation to instrument UnauthorizedController, but you would see another log entry for the Warden request.