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?

Convoy

Could you push your minimal app code to github? Coz, the usual setup is Rack → Warden → Rails and not Rack → Rails → Warden. – Mckeon

@Mckeon Done. Had one more or less ready to go, actually. You can find it here. And yeah, what you're saying makes total sense (it's middleware after all), so it may well be that I've just set everything up completely backwards. – Convoy

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

Loosen

And what do the logs say? Because that's my question. My setup already works for authentication etc., except that the logs do not show which http status was sent to the client. And that's my question – Convoy

@Convoy I think warden is not compatible with rails (only with rack). Thus warden doesn't have embeded Rails.logger. Try to use before_failure callback (I've edited my answer) – Loosen

Sure, I can add whatever additional logging I want in a callback, but I'm interested in having the Rails logger - which seems aware that the request has been responded to - log the response in the same manner as any other response. – Convoy

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.

Proustite