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?

Could you push your minimal app code to github? Coz, the usual setup is `Rack → Warden → Rails` and not `Rack → Rails → Warden`. — Uzbekjon, Jun 24 '16 at 14:38
@Uzbekjon Done. Had one more or less ready to go, actually. You can find it [here](https://github.com/Flambino/WardenLogging_Test). 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. — Flambino, Jun 24 '16 at 16:10

itsnikolay · Answer 1 · 2016-06-26T20:17:30.483

2

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

edited Jun 26 '16 at 20:17

answered Jun 26 '16 at 19:30

itsnikolay

17,415
4
65
64

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 – Flambino Jun 26 '16 at 19:54
@Flambino 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) – itsnikolay Jun 26 '16 at 19:58
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. – Flambino Jun 26 '16 at 21:14

score 1 · Answer 2 · answered Mar 20 '20 at 09:28

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.

No status code in Rails log after Warden auth failure

2 Answers2