Unexpected 401 Unauthorized response status when action is public

[rafaelsales]

The PR #4375 broke the logging in my app when I upgraded from 4.3.0 to 4.4.0, and 4.4.1 is still broken. I'm on Rails 5.1.4

I noticed that the logs in my app had Completed 401 Unauthorized when the actual response received by the client was a 500 Internal Server Error.

I reported this in #4375 (comment) but @tegon suggested to submit this PR with a failing test case that reproduces the bug.

Investigation

I dug in a little bit and I found out that in the following method, the payload[:exception] always returns nil even if a public action raises an error, so the 401 status is added to the payload. Also, Rails didn't add the 500 status at this point yet, so payload[:status] is nil as well

https://github.com/plataformatec/devise/blob/f39c6fd92774cb66f96f546d8d5e8281542b4e78/lib/devise/controllers/helpers.rb#L16-L19

Solution

I couldn't figure out the proper solution other than reverting that PR yet. I'll spend some time investigating later today, but it would be great to have some input from @fbbergamo

Use ActiveSupport::Notifications.instrument instead of overriding append_info_to_payload since the former is called later in the stack, for which the payload[:exception] is present when an exception was raised

[rafaelsales]

This is basically a test case copied from the above one, but using a public action that raises an error (see rest of commit)

This assertion fails unexpectedly:

devise(master)% ruby -I"lib:test" test/integration/authenticatable_test.rb -n /public/

==> Devise.orm = :active_record
Expected string default value for '--orm'; got false (boolean)
Run options: -n /public/ --seed 25980

# Running:

F

Failure:
AuthenticationOthersTest#test_public_action_should_return_notification_payload_with_500_status [test/integration/authenticatable_test.rb:564]:
Expected: 500
  Actual: 401

[mrnugget]

I dug into this a little bit, because we're running into the same wrong log messages. In our case the investigation was triggered by ActiveRecord::RecordNotFound exceptions resulting in 401 instead of 404 being logged. Here's what I found out.

Since this change to Rails, append_info_to_payload is called even if a controller action raised an exception: https://github.com/rails/rails/pull/17978/files

That's good! BUT the payload does not have any value set under :exception:

https://github.com/rails/rails/blob/4b42c7e52aa23081ce02ffad53c76ab786214e87/actionpack/lib/action_controller/metal/instrumentation.rb#L19-L41

That means the code added/changed in #4375 is incorrect. Making it correct would either mean setting :exception in the payload, which would require changes to Rails. I don't know how feasible that is or if we should do it at all as a first course of action when our code is based on a wrong assumption.

So, is there another way to check if an exception was thrown? I don't know of any, especially not in the context in which append_info_to_payload is called: an ensure block. I think one might get to the exception by checking the global $! but I don't know if that one's reset after an exception is handled/rescued/whatever. And if it's not reset, then we'd always think we have an exception on our hands.

If there's no other way, maybe the whole idea of assuming status 401 does not hold anymore? It's based on a pretty old commit for a different mechanism:

1e2dab3

Maybe we should just get rid of it and move the setting of 401 somewhere else?

[rafaelsales]

@mrnugget just made a commit with the proposed fix. The logging was fixed in my Rails app - let me know if you can test it as well and find any issue!

@tegon can you review this?

[mrnugget]

@rafaelsales The proposed fix still contains a reference to payload[:exception], which will never be set (see previous comment of mine). I'm also unsure about the consequences of globally setting 401 as a status. I'd say that scoping this to devise/warden-enabled controllers would be better.

[rafaelsales]

@mrnugget That value is present when the instrument subscription is called, it's just not present when append_info_to_payload is called. I could see that both debugging and when asserting on the spec.

Here's where it gets set by Rails:

https://github.com/rails/rails/blob/3e48bfd49730331d8f09d4d96bb9a58959017a9c/activesupport/lib/active_support/notifications/instrumenter.rb#L17-L29

I agree with the "scoping this to devise/warden-enabled controllers" though. I could add this check in the instrument: payload[:headers]['action_controller.instance'].try(:devise_controller?)
If we revert to use the log_process_action it would also be ok.

[rafaelsales]

Check this out:

[mrnugget]

That value is present when the instrument subscription is called, it's just not present when append_info_to_payload is called. I could see that both debugging and when asserting on the spec.

@rafaelsales Ahh, thanks for clearing that up!

I agree with the "scoping this to devise/warden-enabled controllers" though. I could add this check in the instrument: payload[:headers]['action_controller.instance'].try(:devise_controller?)
If we revert to use the log_process_action it would also be ok.

I know that this might sound excessive, but I'm kind of wary of calling a method (trough an indirect try!) on a controller "just for logging". And I also don't really like the modifying of the payload. That being said, I'm not super knowledgable in regards to ActiveSupport::Notifications, so those might be best practices.

[abarrak]

Thank you @rafaelsales for taking the time to resolve this.

I’m witnessing this too after upgrading to 5.1.4, when a 500 exception is returned within action.

[rafaelfranca]

I'm more included to revert the previous PR. The right place to implement that is inside the controller instance, not inside a new subscriber.

[mrnugget]

I'm more included to revert the previous PR. The right place to implement that is inside the controller instance, not inside a new subscriber.

If that option is on the table, I think it's the best one.

[rafaelsales]

@rafaelfranca @mrnugget Yeah, I also agree that reverting to the old approach is cleaner.

I just tried reverting to the old implementation while keeping the specs to make sure a regression is not introduced in the future, but I couldn't get this spec that @fbbergamo wrote originally to work.

https://github.com/rafaelsales/devise/blob/45048ee3053103d53840618760a3f3ac85846d21/test/integration/authenticatable_test.rb#L549-L560

I keep getting:

Failure:
AuthenticationOthersTest#test_not_signed_in_should_return_notification_payload_with_401_status_haha [test/integration/authenticatable_test.rb:554]:
Expected: 401
  Actual: nil

[tegon]

I'm going to revert the previous PR and release a patch version - we also have other bug fixes to include in this release - then we can think of another solution to the previous issue.

[rafaelsales]

Thanks!

[AndrewSouthpaw]

Did this only get reverted back and never actually solved?

[tegon]

@AndrewSouthpaw I only saw your comment now while I was digging for this. Indeed, it wasn't solved yet. We decided to revert because we needed to release a version with some important fixes, but this wasn't addressed yet.
Can you open another issue for this? Thanks.

[AndrewSouthpaw]

Done!