lograge: extracting status does fail with devise when authentication fails

Status code 0 instead of 401 here as well, lograge 0.11.2, Rails 5.2.4.3, Devise 4.7.3

the PR was reverted lol

I ran into this issue too and dug a bit deeper. It happens because devise sets the status here:

https://github.com/plataformatec/devise/blob/master/lib/devise/controllers/helpers.rb#L77

which is usually called by rails here:

https://github.com/rails/rails/blob/master/actionpack/lib/action_controller/log_subscriber.rb#L21

However, lograge uses its own LogSubscriber to process the notifications from rails:

https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscriber.rb#L8

The easy fix would be to call ActionController::Base.log_process_action(payload) from the lograge code, however, this doesn’t seem right to me.

I spent some time investigating this. This issue uncovered a number of issues:

1. Devise shouldn’t be using ActionController::Base.log_process_action to mutate payload; that wasn’t really the design of that API call (https://github.com/rails/rails/blob/06dd162fb3ae67f202a0a59da1ce94317d0a3e22/actionpack/lib/action_controller/metal/instrumentation.rb#L96-L98). The workaround in https://github.com/roidrage/lograge/pull/194 forces a status code if there isn’t one, but it’s not necessarily the correct status code. It will always display a 401 error code if no status or exception is available. I can make Devise throw a 404 in the failure app, but the logs will always show a 401.

2. https://github.com/heartcombo/devise/pull/4375 causes the wrong error codes to be reported because append_info_to_payload doesn’t have access to the payload[:exception] object. The exception is added later in https://github.com/rails/rails/blob/997770f5955a36f0c800388c4592c961e184aec4/activesupport/lib/active_support/notifications/instrumenter.rb#L26:

activesupport-6.0.2/lib/active_support/notifications/instrumenter.rb:25:in `instrument'
activesupport-6.0.2/lib/active_support/notifications.rb:180:in `instrument'
actionpack-6.0.2/lib/action_controller/metal/instrumentation.rb:32:in `process_action' <--- This is where append_info_to_payload is called
actionpack-6.0.2/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
activerecord-6.0.2/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
actionpack-6.0.2/lib/abstract_controller/base.rb:136:in `process'
actionview-6.0.2/lib/action_view/rendering.rb:39:in `process'
actionpack-6.0.2/lib/action_controller/metal.rb:191:in `dispatch'
actionpack-6.0.2/lib/action_controller/metal.rb:252:in `dispatch'
actionpack-6.0.2/lib/action_dispatch/routing/route_set.rb:51:in `dispatch'
actionpack-6.0.2/lib/action_dispatch/routing/route_set.rb:33:in `serve'
actionpack-6.0.2/lib/action_dispatch/journey/router.rb:49:in `block in serve'
actionpack-6.0.2/lib/action_dispatch/journey/router.rb:32:in `each'
actionpack-6.0.2/lib/action_dispatch/journey/router.rb:32:in `serve'
actionpack-6.0.2/lib/action_dispatch/routing/route_set.rb:837:in `call'

1. I noticed if I threw an exception inside the Devise FailureApp, the Rails log subscriber would never actually see it. It looks like the Devise failures are directed to a Rails metal controller that isn’t instrumented with the standard logger. I can add notifications via this change:

$ git diff
diff --git a/lib/devise/failure_app.rb b/lib/devise/failure_app.rb
index 7f80733c..3dc6b81f 100644
--- a/lib/devise/failure_app.rb
+++ b/lib/devise/failure_app.rb
@@ -15,6 +15,7 @@ module Devise
     include Rails.application.routes.mounted_helpers

     include Devise::Controllers::StoreLocation
+    include ActionController::Instrumentation

     delegate :flash, to: :request

However, this generates two log entries: one for /users/sign_in and one for an internal /unauthenticated endpoint:

{
  "method": "POST",
  "path": "/users/sign_in",
  "format": "html",
  "controller": "SessionsController",
  "action": "create",
  "status": 0,
  "duration": 694.72,
  "view": 0,
  "db": 13.75,
  "time": "2020-03-20T08:42:35.185Z",
  "params": [
    {
      "key": "utf8",
      "value": "✓"
    },
    {
      "key": "authenticity_token",
      "value": "[FILTERED]"
    },
    {
      "key": "user",
      "value": {
        "login": "root",
        "password": "[FILTERED]",
        "remember_me": "0"
      }
    }
  ]
}

{
  "method": "POST",
  "path": "/unauthenticated",
  "format": "html",
  "controller": "Gitlab::DeviseFailure",
  "action": "respond",
  "status": 404,
  "duration": 2.19,
  "view": 0,
  "time": "2020-03-20T08:42:35.191Z",
  "params": [
    {
      "key": "utf8",
      "value": "✓"
    },
    {
      "key": "authenticity_token",
      "value": "[FILTERED]"
    },
    {
      "key": "user",
      "value": {
        "login": "root",
        "password": "[FILTERED]",
        "remember_me": "0"
      }
    }
  ],
  "exception.class": "ActiveRecord::RecordNotFound",
  "exception.message": "ActiveRecord::RecordNotFound",
  "exception.backtrace": [
    "lib/gitlab/devise_failure.rb:18:in `respond'"
  ]
}

Ideally, we’d combine these two entries into one, but I’m not sure whether that’s easy right now. This may be a limitation of the way all this instrumentation works. I think the request is going from Rails -> Rack -> Warden -> Warden failure app. As far as the Rails controller goes, it finishes processing the request with a nil status code, and that’s when Lograge gets called. But then the Warden middleware runs and returns the correct status code.

Sadly not it seems. I’ll reopen this and take a look today.

The devise issue is caused by the problem described here: plataformatec/devise#4375.

Despite the apparent failure by lograge to accommodate this I’m reluctant to handle the special case caused by devise.

@brucew If you’re experiencing issues outside of devise - post a reproduction for me to investigate.

I came across this issue today. Does anyone have a solution for it?

It’s merged! https://github.com/plataformatec/devise/pull/4375