Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Can't logout of user account after upgrade to v3.4.3 #16949

Closed
rodti opened this issue Nov 6, 2021 · 36 comments
Closed

Can't logout of user account after upgrade to v3.4.3 #16949

rodti opened this issue Nov 6, 2021 · 36 comments
Labels
bug Something isn't working

Comments

@rodti
Copy link

rodti commented Nov 6, 2021

Expected behaviour

Follow standard logout process in interface, user is logged out.

Actual behaviour

Follow standard logout process in interface, user is not logged out.

Steps to reproduce the problem

  1. User is already logged in and in standard Mastodon interface view
  2. Select logout icon at top left of Mastodon interface or 'Logout' text on right (above 'Mastodon is open source...' text
  3. Select 'LOG OUT' button on 'Are you sure you want to log out?' prompt

Specifications

v3.4.3

This occurs on macOS 12.0.1 with Safari 15.1 (17612.2.9.1.20)

It doesn't seem to be an issue on Chrome.

The user account can still be logged out from the Preferences page.

It has been proven to be an issue on two separate instances with identical configuration.

@rodti rodti added the bug Something isn't working label Nov 6, 2021
@ClearlyClaire
Copy link
Contributor

What occurs exactly when selecting the “log out” button on the “Are you sure you want to log out?” prompt? Do you know if it worked on v3.4.1 or earlier?

@rodti
Copy link
Author

rodti commented Nov 6, 2021

Definitely worked in v3.4.1 and before. From memory I believe it returned you to a login screen when you press ‘LOG OUT’. It now returns you to the standard view of your timelines.

@ClearlyClaire
Copy link
Contributor

Weird. I can't think of a reason it would behave this way, and I cannot reproduce it using Firefox. Unfortunately, I do not have access to Safari to try reproducing it.

@rodti
Copy link
Author

rodti commented Nov 6, 2021

The only thing that was different to a normal upgrade was that I was prompted to update the following:

npx browserslist@latest --update-db

It might be a Safari specific issue. I remember reporting a media upload/playback issue that only affected Safari a while back. The problem with this one is that partially restricting the ability of a user to logout could present a security risk on shared machines etc.

@ClearlyClaire
Copy link
Contributor

ClearlyClaire commented Nov 8, 2021

Yes, I understand that is an issue. But I don't understand why it is happening.

Can you reproduce it reliably, or does it not always happen? If you have admin access to your instance, you may try applying the following to have some more debug info:

diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index 5232e6cfd..4f0b08e85 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -1,9 +1,13 @@
 require 'devise/strategies/authenticatable'
 
-Warden::Manager.after_set_user except: :fetch do |user, warden|
+Warden::Manager.after_set_user except: :fetch do |user, warden, opts|
+  Rails.logger.warn "set_user: #{user.id} (opts: #{opts.inspect})"
+
   if user.session_active?(warden.cookies.signed['_session_id'] || warden.raw_session['auth_id'])
+    Rails.logger.warn "set_user reusing session for #{user.id}"
     session_id = warden.cookies.signed['_session_id'] || warden.raw_session['auth_id']
   else
+    Rails.logger.warn "set_user creating new session for #{user.id}"
     session_id = user.activate_session(warden.request)
   end
 
@@ -17,6 +21,8 @@ Warden::Manager.after_set_user except: :fetch do |user, warden|
 end
 
 Warden::Manager.after_fetch do |user, warden|
+  Rails.logger.warn "after_fetch! #{user.id}"
+
   if user.session_active?(warden.cookies.signed['_session_id'] || warden.raw_session['auth_id'])
     warden.cookies.signed['_session_id'] = {
       value: warden.cookies.signed['_session_id'] || warden.raw_session['auth_id'],
@@ -31,7 +37,8 @@ Warden::Manager.after_fetch do |user, warden|
   end
 end
 
-Warden::Manager.before_logout do |_, warden|
+Warden::Manager.before_logout do |user, warden|
+  Rails.logger.warn "before logout! for #{user.id}"
   SessionActivation.deactivate warden.cookies.signed['_session_id']
   warden.cookies.delete('_session_id')
 end

I'm interested in the sequence of actions occurring when logging out from Safari.

@rodti
Copy link
Author

rodti commented Nov 8, 2021

Yep, it happens consistently on multiple user accounts, two different instances, and on both desktop and mobile versions of Safari, so can definitely be reproduced. I'm admin on two instances so happy to help 😂

@ClearlyClaire
Copy link
Contributor

@rodti can you apply the patch above, reload mastodon-web, and check the logs when logging out from Safari?

ClearlyClaire added a commit to ClearlyClaire/mastodon that referenced this issue Nov 9, 2021
@ClearlyClaire
Copy link
Contributor

I borrowed an iPad and did not manage to reproduce the issue, so I really don't understand what may be causing the issue. It would help if you could post the logs after applying the patch in #16949 (comment) ; also, do you have anything unusual (browser extensions, etc.) on your setup?

Finally, if the issue can be reliably reproduced, can you try #16972 and see if it fixes the issue?

@rodti
Copy link
Author

rodti commented Nov 10, 2021

Hi there, apologies for my slow reply, I've been away for a few days with limited connectivity. I do have admin access on two affected instances but not entirely clear how to apply the patch you've posted in #16949 (comment)

@ClearlyClaire
Copy link
Contributor

patch -p1 then paste the contents and press ctrl+D

@rodti
Copy link
Author

rodti commented Nov 11, 2021

No change to functionality after applying that patch. This is what I'm seeing in the logs when I login as a user and then try to logout again:

Nov 11 11:54:52 mastodon bundle[180412]: [141dd063-ec61-46b2-86f9-8b05dcce46f5] config/initializers/devise.rb:41:in `block in <top (required)>'
Nov 11 11:54:52 mastodon bundle[180412]: [3219eff2-0dbe-44be-af94-b675bc808fc5] set_user: 91 (opts: {:scope=>:user, :store=>true, :event=>:authentication})
Nov 11 11:54:52 mastodon bundle[180412]: [3219eff2-0dbe-44be-af94-b675bc808fc5] set_user creating new session for 91
Nov 11 11:54:52 mastodon bundle[180412]: [316ae615-01d2-443d-a9ea-976beba60dea] after_fetch! 91
Nov 11 11:54:53 mastodon bundle[180412]: [f68a6985-ace2-447b-83e5-616b7653c3b2]
Nov 11 11:54:53 mastodon bundle[180412]: [f68a6985-ace2-447b-83e5-616b7653c3b2] NoMethodError (undefined method `id' for nil:NilClass):
Nov 11 11:54:53 mastodon bundle[180412]: [f68a6985-ace2-447b-83e5-616b7653c3b2]
Nov 11 11:54:53 mastodon bundle[180412]: [f68a6985-ace2-447b-83e5-616b7653c3b2] config/initializers/devise.rb:41:in `block in <top (required)>'

The NoMethodError and config/initializers/devise.rb lines repeat frequently in the logs.

@ClearlyClaire
Copy link
Contributor

This is really odd, I can't understand how it could be called with a nil value, and even less how it could be a change fro v3.4.3…

Can you apply the following patch on top of the previous one and try again?

diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index 4f0b08e85..750ca3469 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -37,8 +37,8 @@ Warden::Manager.after_fetch do |user, warden|
   end
 end
 
-Warden::Manager.before_logout do |user, warden|
-  Rails.logger.warn "before logout! for #{user.id}"
+Warden::Manager.before_logout do |user, warden, opts|
+  Rails.logger.warn "before logout! for #{user&.id.inspect} ; #{warden.cookies.signed['_session_id'][..4]} ; #{opts.inspect}"
   SessionActivation.deactivate warden.cookies.signed['_session_id']
   warden.cookies.delete('_session_id')
 end

@rodti
Copy link
Author

rodti commented Nov 11, 2021

New patch applied, same issues:

Nov 11 12:10:04 mastodon bundle[181040]: [fc8d1cfa-fbc2-479d-a788-89c7f0bd06f6] config/initializers/devise.rb:41:in `block in <top (required)>'
Nov 11 12:10:04 mastodon bundle[181040]: [91c25215-b981-466c-acb3-fa8d2c91ce15] set_user: 91 (opts: {:scope=>:user, :store=>true, :event=>:authentication})
Nov 11 12:10:04 mastodon bundle[181040]: [91c25215-b981-466c-acb3-fa8d2c91ce15] set_user creating new session for 91
Nov 11 12:10:05 mastodon bundle[181040]: [8357e0d4-91bb-4ec4-9a4c-ef18eb26ecf5] after_fetch! 91
Nov 11 12:10:05 mastodon bundle[181040]: [12266d16-fc43-4819-a3c0-ab7707250f89]
Nov 11 12:10:05 mastodon bundle[181040]: [12266d16-fc43-4819-a3c0-ab7707250f89] NoMethodError (undefined method `[]' for nil:NilClass):
Nov 11 12:10:05 mastodon bundle[181040]: [12266d16-fc43-4819-a3c0-ab7707250f89]
Nov 11 12:10:05 mastodon bundle[181040]: [12266d16-fc43-4819-a3c0-ab7707250f89] config/initializers/devise.rb:41:in `block in <top (required)>'

@ClearlyClaire
Copy link
Contributor

… ok… apply this patch and try again:

diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index 750ca3469..f9d608c59 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -38,6 +38,10 @@ Warden::Manager.after_fetch do |user, warden|
 end
 
 Warden::Manager.before_logout do |user, warden, opts|
+  if warden.cookies.signed['_session_id'].nil?
+    Rails.logger.warn "before logout! called with nil user??"
+    return
+  end
   Rails.logger.warn "before logout! for #{user&.id.inspect} ; #{warden.cookies.signed['_session_id'][..4]} ; #{opts.inspect}"
   SessionActivation.deactivate warden.cookies.signed['_session_id']
   warden.cookies.delete('_session_id')

@rodti
Copy link
Author

rodti commented Nov 11, 2021

Thanks for all your help with this, still having issues but the errors are now moving to line 43:

Nov 11 13:04:27 mastodon bundle[181768]: [2f3e2908-8c33-418a-9545-8012a6d6c54b] config/initializers/devise.rb:43:in `block in <top (required)>'
Nov 11 13:04:29 mastodon bundle[181768]: [d5256025-0ed3-43c5-839d-9118953bf0d2] before logout! called with nil user??
Nov 11 13:04:29 mastodon bundle[181768]: [d5256025-0ed3-43c5-839d-9118953bf0d2]
Nov 11 13:04:29 mastodon bundle[181768]: [d5256025-0ed3-43c5-839d-9118953bf0d2] LocalJumpError (unexpected return):
Nov 11 13:04:29 mastodon bundle[181768]: [d5256025-0ed3-43c5-839d-9118953bf0d2]
Nov 11 13:04:29 mastodon bundle[181768]: [d5256025-0ed3-43c5-839d-9118953bf0d2] config/initializers/devise.rb:43:in `block in <top (required)>'
Nov 11 13:04:30 mastodon bundle[181768]: [9004d30d-ce06-4e9e-9ece-0fbff03e36fd] before logout! called with nil user??
Nov 11 13:04:30 mastodon bundle[181768]: [9004d30d-ce06-4e9e-9ece-0fbff03e36fd]
Nov 11 13:04:30 mastodon bundle[181768]: [9004d30d-ce06-4e9e-9ece-0fbff03e36fd] LocalJumpError (unexpected return):
Nov 11 13:04:30 mastodon bundle[181768]: [9004d30d-ce06-4e9e-9ece-0fbff03e36fd]
Nov 11 13:04:30 mastodon bundle[181768]: [9004d30d-ce06-4e9e-9ece-0fbff03e36fd] config/initializers/devise.rb:43:in `block in <top (required)>'
Nov 11 13:04:32 mastodon bundle[181768]: [30c8d8cb-f99d-49d7-a296-01aca058e1d3] before logout! called with nil user??
Nov 11 13:04:32 mastodon bundle[181768]: [30c8d8cb-f99d-49d7-a296-01aca058e1d3]
Nov 11 13:04:32 mastodon bundle[181768]: [30c8d8cb-f99d-49d7-a296-01aca058e1d3] LocalJumpError (unexpected return):
Nov 11 13:04:32 mastodon bundle[181768]: [30c8d8cb-f99d-49d7-a296-01aca058e1d3]
Nov 11 13:04:32 mastodon bundle[181768]: [30c8d8cb-f99d-49d7-a296-01aca058e1d3] config/initializers/devise.rb:43:in `block in <top (required)>'
Nov 11 13:04:34 mastodon bundle[181768]: [92e61fd0-5235-4119-8c58-7cf0e9cdbf24] before logout! called with nil user??
Nov 11 13:04:34 mastodon bundle[181768]: [92e61fd0-5235-4119-8c58-7cf0e9cdbf24]

@rodti
Copy link
Author

rodti commented Nov 11, 2021

I've now tested it in Google Chrome, Internet Explorer and Firefox, all of which work as expected. On the current build of Safari on macOS Monterey, iOS 15 and iPadOS 15 I experience this issue. Really strange that it worked on your iPad though?

I wonder if it could be anything specific to the upgrade, but I've followed the standard upgrade process (which I've done many times before!) on both instances.

@ClearlyClaire
Copy link
Contributor

ClearlyClaire commented Nov 11, 2021

Can you retry with this patch?

diff --git a/app/controllers/auth/sessions_controller.rb b/app/controllers/auth/sessions_controller.rb
index 630b0dee5..a933d2174 100644
--- a/app/controllers/auth/sessions_controller.rb
+++ b/app/controllers/auth/sessions_controller.rb
@@ -29,6 +29,7 @@ class Auth::SessionsController < Devise::SessionsController
   end
 
   def destroy
+    Rails.logger.warn "called /auth/sign_out; #{current_user&.id} ; session present? #{cookies.signed['_session_id'].present?}"
     tmp_stored_location = stored_location_for(:user)
     super
     session.delete(:challenge_passed_at)
diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index f9d608c59..fbac6b59e 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -40,11 +40,11 @@ end
 Warden::Manager.before_logout do |user, warden, opts|
   if warden.cookies.signed['_session_id'].nil?
     Rails.logger.warn "before logout! called with nil user??"
-    return
+  else
+    Rails.logger.warn "before logout! for #{user&.id.inspect} ; #{warden.cookies.signed['_session_id'][..4]} ; #{opts.inspect}"
+    SessionActivation.deactivate warden.cookies.signed['_session_id']
+    warden.cookies.delete('_session_id')
   end
-  Rails.logger.warn "before logout! for #{user&.id.inspect} ; #{warden.cookies.signed['_session_id'][..4]} ; #{opts.inspect}"
-  SessionActivation.deactivate warden.cookies.signed['_session_id']
-  warden.cookies.delete('_session_id')
 end
 
 module Devise
diff --git a/config/initializers/suppress_csrf_warnings.rb b/config/initializers/suppress_csrf_warnings.rb
index b86adc6f1..bfde38ff5 100644
--- a/config/initializers/suppress_csrf_warnings.rb
+++ b/config/initializers/suppress_csrf_warnings.rb
@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 Rails.application.reloader.to_prepare do
-  ActionController::Base.log_warning_on_csrf_failure = false
+  ActionController::Base.log_warning_on_csrf_failure = true
 end

Also, is there any error in the browser's debug console when logging out?

@rodti
Copy link
Author

rodti commented Nov 11, 2021

I've created an account on mastodon.online which works as expected, both in simple and advanced web interfaces, so this seems to be limited to the two instances I've upgraded to v3.4.3.

@rodti
Copy link
Author

rodti commented Nov 11, 2021

Last patch has changed the error again!

Nov 11 13:26:04 mastodon bundle[182207]: [d7e08f86-ca62-42f7-b39f-6d3c3cdc0ea7] Can't verify CSRF token authenticity.
Nov 11 13:26:04 mastodon bundle[182207]: [d7e08f86-ca62-42f7-b39f-6d3c3cdc0ea7] before logout! called with nil user??

@ClearlyClaire
Copy link
Contributor

Does reloading the page before clicking the logout link help? What's the output when logging out from another browser? When logging out from the settings page?

@mfa777
Copy link

mfa777 commented Nov 12, 2021

Hi, I had same issue. It happened on safari of iPhone and MacOS.

For my instance, the problem looks come from frontend, rather than backend. When I click this button, The layer just close itself, and nothing happened.

image

I try to use tools to watch the network traffic, Then I notice there's no any request was sent when I click that button.

And safari console has no error. I am not familiar with react so I could not find the way to debug it.

For my environment, I use self-build docker version and same code base with 3.4.3.

@ClearlyClaire
Copy link
Contributor

Ok I'm pretty confused for several reasons:

  • @rodti's logs show that the server-side codepath for logging out is reached, albeit with unusual parameters. I can't fully explain that, and I don't understand why it would behave differently browser-to-browser.
  • “Can't verify CSRF token authenticity.” appearing in those logs seems to hint at one thing I overlooked when making the logging out changes, but I do not understand how it would only trigger with Safari, and I'm surprised there isn't actually a user-facing error instead: if the CSRF token is incorrect, one should get “401 The access token is invalid” instead of the timeline logging, and “Security verification failed. Are you blocking cookies?” when logging out.
  • @mfa777 points to another direction entirely, which I will investigate, but I'm confused since @rodti's reports seem to indicate an actual network query being performed…

@mfa777
Copy link

mfa777 commented Nov 12, 2021

I watched my log, there's no request of SessionsController for 'destroy' action.

But if I logout from here, there is.

image

@ClearlyClaire
Copy link
Contributor

@rodti could you reply to the questions I asked in this comment? #16949 (comment)
Also, could you then revert our previous changes (git checkout -- config/initializers/devise.rb) and try those following patches (testing them one after the other) and see if they help?

Patch 1:

diff --git a/app/controllers/auth/sessions_controller.rb b/app/controllers/auth/sessions_controller.rb
index 0184bfb52..b9fe1ed7b 100644
--- a/app/controllers/auth/sessions_controller.rb
+++ b/app/controllers/auth/sessions_controller.rb
@@ -148,6 +148,7 @@ class Auth::SessionsController < Devise::SessionsController
     clear_attempt_from_session
 
     user.update_sign_in!(request, new_sign_in: true)
+    remember_me(user)
     sign_in(user)
     flash.delete(:notice)
 
@@ -170,4 +171,17 @@ class Auth::SessionsController < Devise::SessionsController
       user_agent: request.user_agent
     )
   end
+
+  def remember_me(user)
+    session_id = cookies.signed['_session_id']
+    session_id = user.activate_session(request) unless user.session_active?(session_id)
+
+    cookies.signed['_session_id'] = {
+      value: session_id,
+      expires: 1.year.from_now,
+      httponly: true,
+      secure: (Rails.env.production? || ENV['LOCAL_HTTPS'] == 'true'),
+      same_site: :lax,
+    }
+  end
 end
diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index 5232e6cfd..a7cb065f8 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -1,21 +1,5 @@
 require 'devise/strategies/authenticatable'
 
-Warden::Manager.after_set_user except: :fetch do |user, warden|
-  if user.session_active?(warden.cookies.signed['_session_id'] || warden.raw_session['auth_id'])
-    session_id = warden.cookies.signed['_session_id'] || warden.raw_session['auth_id']
-  else
-    session_id = user.activate_session(warden.request)
-  end
-
-  warden.cookies.signed['_session_id'] = {
-    value: session_id,
-    expires: 1.year.from_now,
-    httponly: true,
-    secure: (Rails.env.production? || ENV['LOCAL_HTTPS'] == 'true'),
-    same_site: :lax,
-  }
-end
-
 Warden::Manager.after_fetch do |user, warden|
   if user.session_active?(warden.cookies.signed['_session_id'] || warden.raw_session['auth_id'])
     warden.cookies.signed['_session_id'] = {

Patch 2:

diff --git a/config/initializers/devise.rb b/config/initializers/devise.rb
index f9d608c59..a4612bf8a 100644
--- a/config/initializers/devise.rb
+++ b/config/initializers/devise.rb
@@ -111,6 +111,10 @@ module Devise
         end
       end
 
+      def clean_up_csrf?
+        false
+      end
+
       private
 
       def session_cookie

@ClearlyClaire
Copy link
Contributor

Oh dang, I was writing a patch for what I understood of @mfa777's report and… #16574

This has already been solved, just not in 3.4.3. Still, I'm curious about @rodti's logs, they are weird.

@rodti
Copy link
Author

rodti commented Nov 12, 2021

Does reloading the page before clicking the logout link help? What's the output when logging out from another browser? When logging out from the settings page?

Reloading the page before clicking logout doesn't make any difference. Will have a look again at other browsers later on.

@rodti
Copy link
Author

rodti commented Nov 12, 2021

Oh dang, I was writing a patch for what I understood of @mfa777's report and… #16574

This has already been solved, just not in 3.4.3. Still, I'm curious about @rodti's logs, they are weird.

When you say 'not in 3.4.3' I take it they're going to be included in a later release? Is it worth me adding those changes to see if it fixes my issues?

@ClearlyClaire
Copy link
Contributor

It is going to be included in a later release, at least the next major one, if not in a minor release before that. You can cherry-pick the changes from #16574, it will most definitely fix your issues.

I'm still curious to know whether the changes in #16949 (comment) fix anything for you without the front-end changes, due to your weird logs, though.

@rodti
Copy link
Author

rodti commented Nov 12, 2021

First patch gives this error:

patching file app/controllers/auth/sessions_controller.rb
Hunk #1 FAILED at 148.
Hunk #2 succeeded at 150 with fuzz 2 (offset -20 lines).
1 out of 2 hunks FAILED -- saving rejects to file app/controllers/auth/sessions_controller.rb.rej
patching file config/initializers/devise.rb

I've tried both patches and neither fix the issue. I made sure to revert previous changes first as per your instruction.

@ClearlyClaire
Copy link
Contributor

ah, yes, the patch doesn't apply cleanly on v3.4.3, sorry. Nevermind then, I thin the front-end change is the proper fix. I'm still confused at your weird logs though.

@rodti
Copy link
Author

rodti commented Nov 12, 2021

It is going to be included in a later release, at least the next major one, if not in a minor release before that. You can cherry-pick the changes from #16574, it will most definitely fix your issues.

I've applied those changes and they don't fix the issue! I'll double check they've all been applied correctly. I restarted the web service afterwards.

@ClearlyClaire
Copy link
Contributor

Did you run bundle exec rails assets:precompile before restarting the web service?

@rodti
Copy link
Author

rodti commented Nov 12, 2021

Did you run bundle exec rails assets:precompile before restarting the web service?

Ah! No I didn't, and now it works. Sorry for that, multitasking badly here. Thanks for all your help!

@tigransimonyan
Copy link

I have same problem.

@ClearlyClaire
Copy link
Contributor

I have same problem.

Yeah, the problem has been confirmed, and is fixed by #16574. You can cherry-pick this change, or wait for a new version.

@ClearlyClaire
Copy link
Contributor

Fixed in 3.4.4

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants