extracting status does fail with devise when authentication fails

[tisba]

(I'm using rails 4.0.3, devise 3.2.3 and lograge 0.3.0.)

I'm not sure if this is really devise devise specific. When I make a request that fails authentication it returns a 401 Unauthorized. lograge does log this with status=0 though. When I look at payload in https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscriber.rb#L56-L65, I get

{:controller=>"TestsController", :action=>"index", :params=>{"action"=>"index", "controller"=>"tests"}, :format=>"*/*", :method=>"GET", :path=>"/tests"}

which is obviously the reason why status=0 gets logged.

With lograge disabled I get this log entry by rails:

Started GET "/tests" for 127.0.0.1 at 2014-03-14 10:45:49 +0100
Processing by TestsController#index as */*
Completed 401 Unauthorized in 8ms

I'm wondering if I am overlooking something here and if this can be somehow fixed. Anyone else seeing this issue?

[marshally]

I'm also seeing this issue on device sign_in/sign_out endpoints.

[kuinak]

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.

[rylwin]

I ran into this same problem in our production app today and in order to help confirm the source I made a small rails app. I should have looked here first as it seems the culprit has already been identified! In case it's helpful I'll still drop the link here: https://github.com/rylwin/lograge-devise-test.

[wagner]

I've managed to log a 401 overriding Devise::SessionsController#new and responding with a status: :unauthorized. Not proud tho.

[milgner]

Just encountered this problem, too. Since the issue was closed a few days ago, does this mean that it has been fixed in upstream?

[benlovell]

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

[mikaelhm]

Just encountered this too.
Why is @kuinak's suggestion problematic?

The easy fix would be to call ActionController::Base.log_process_action(payload) from the lograge code

[bradseefeld]

We have been having this issue as well.

http://stackoverflow.com/questions/42142503/rails-server-returning-http-status-0

In our case, its because CSRF fails. However, we do use devise, but from a few requests I have sampled, its not caused by a devise 401. In all our cases, its because of the protect_from_forgery issuing a redirect to our sign in page.

[brucew]

I am having this issue since switching to Lograge 3 months ago and like @bradseefeld it doesn't appear to be just Devise 401s. Using Lograge 0.4.1 with Rails 4.2.8 and Devise 4.2.1. I'm surprised this has been an issue since March 2014.

[benlovell]

The devise issue is caused by the problem described here: heartcombo/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.

[robinw777]

there is a PR in devise might fix this heartcombo/devise#4375

[kofronpi]

Any updates about this ? Should we just wait for the PR to be merged ?

[fbbergamo]

It's merged!
heartcombo/devise#4375

[benlovell]

😍

[rayway30419]

the PR was reverted lol

[steakchaser]

Can confirm this is still an issue with the latest version of Devise (4.7.1) and Lograge (0.11.2). Is anyone aware of a workaround?

I don't understand what this means:

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.

[stanhu]

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 Call log_process_action so that we get status code from Devise controllers #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. Replace log_process_action to append_info_to_payload heartcombo/devise#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'

3. 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.

[dnalbach]

@stanhu I'm seeing these status code 0 log entries with Rails 5.2.3 and Lograge 0.11.2 but sentry.io is showing response status code 0 in the React front-end with axios 0.18.1. It looks like what you wrote above is that Warden corrects the nil status code, but is that always true? Does the Rails controller ever return status code 0 to the client like what I'm seeing in sentry?

[GProst]

We also see status code 0 instead of 401, v0.11.2

[kraila]

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

[chrismanderson]

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

[flivni]

This bug was fixed and the issue was closed. Then the fix was reverted since it was deemed to have too broad an effect. There is now a new bug that tracks the issue:
heartcombo/devise#4914

[emilyst]

It looks like there is an actual fix: #360. But it has not been merged or otherwise acknowledged.