Page MenuHomePhabricator

AuthManager tokens don't match so HTML forms like login fail
Open, Needs TriagePublic

Description

Steps to reproduce

  • Download mediawiki 1.28 wmf 6 and mediawiki vendor.
  • Install mediawiki.
  • THen go to your website where you installed mediawiki.

Actual results

  • Logging in is causing me to get this error

There seems to be a problem with your login session; this action has been canceled as a precaution against session hijacking. Go back to the previous page, reload that page and then try again.

I removed all my extensions to test and still caused that error.

Expected results

  • Logging in should work as it was before.
  • Even setting the disable auth manager config still causing me not to be logged in but shows a cookie error instead.

Event Timeline

Paladox created this task.Jun 19 2016, 12:10 PM
Restricted Application added subscribers: Zppix, Aklapper. · View Herald TranscriptJun 19 2016, 12:10 PM

But on my main wiki en the problem happends but on pt-br.random-wikisaur.tk which I doint use very often the problem dosent happen. but the workaround I found to login into my en website is to use pt-br since it uses en as it's centralauth database.

Actually I just updated the pt-br wiki now. And I carn't seem to use centralauth to login into en but centralauth and login work on my pt-br wiki. Which is strange.

Can we set this as a high priority please. Since ConfirmAccount save a lot of time dealing with spam. Currently it being broken makes it hard to deal with spam when there is spam.

Tgr added a comment.Jun 19 2016, 3:31 PM

Do you have a test account with which I can try this?

@Tgr I can setup a test account.

This comment was removed by Paladox.
Tgr added a comment.Jun 19 2016, 9:01 PM

Can't reproduce on Chrome 50 on Ubuntu (neither normal nor incognito mode).

@Tgr oh, I have the problem on widows. But iOS is not having the problem which I find strange. It carn't be caching can it since I am on the insider programme which means I get a lot builds to install which recently I installed two.

Aklapper renamed this task from Auth Manager is now blocking me from loggin in with invalid CSRF token error to Auth Manager log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki.Jun 20 2016, 8:50 AM
Anomie renamed this task from Auth Manager log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki to Log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki.Jun 20 2016, 2:10 PM
Anomie added a subscriber: Anomie.

Even setting the disable auth manager config still causing me not to be logged in but shows a cookie error instead.

Then the title "Auth Manager log-in fails" isn't accurate, is it?

It sounds like you're having some sort of an issue with cookie handling.

But it happends on chrome and edge. I presume that it shoulder happen on chrome since it won't be sharing cookies with internet explorer. But this problem seems to happen to devices I logged in previously before auth manager was added.

Try capturing the HTTP requests and responses for the entire login process, both loading Special:UserLogin and submitting it. It would also likely be helpful to capture debug-level logs from MediaWiki on at least the 'session', 'cookie', and 'authentication' channels.

@Paladox: Do you plan to provide these logs or shall this task get declined?

@Aklapper Hi, I doint know how to get the logs, I look in the error logs and nothing but unrelated errors are in there.

@Anomie Hi, how do I the logs for you (HTTP requests) please.

For capturing HTTP requests and responses you can use your web browser's Developer Tools.

Paladox added a comment.EditedJul 12 2016, 10:37 AM

In internet explorer is that the network tab (profiling session activity) please

MSDN should have some documentation, I hope...?

Cboltz added a subscriber: Cboltz.Aug 21 2016, 10:59 PM
Subfader added a subscriber: Subfader.EditedSep 7 2016, 9:11 AM

I have the same problem on a fresh installation on

Logs: https://www.mediawiki.org/wiki/Topic:Tb2fn0yu0akq4rz3

I blame trySubmit() in /includes/specialpage/AuthManagerSpecialPage.php

$requestTokenValue and $sessionToken are always different so the match() fails.

[log] requestTokenValue 81cba7c635a8586444bb69f51211cd1657cfe039+\
[log] sessionToken 19735cf19bd8e50b9750ec6cb2a9285057cfe083+\

Since it fails there already, no cookies are set.

But the message authform-notoken is thrown. scratches head

Complete show stopper.

Failed tests:

  • Check console
  • Delete all cookies
  • Disable javascript
  • Run /maintenance/resetUserTokens.php
Subfader triaged this task as Unbreak Now! priority.Sep 7 2016, 9:12 AM
Restricted Application added subscribers: Jay8g, Luke081515, TerraCodes. · View Herald TranscriptSep 7 2016, 9:12 AM

Clearing you cookies should work, but yeh this should be fixed since I doint want to keep clearing my cookies eveytime internet explorer decides to not work with that token.

Subfader added a comment.EditedSep 7 2016, 9:18 AM

My test instance is on a subdomain, but I cleared all cookies, disabled JS, checked console. nothing.

Subfader added a comment.EditedSep 7 2016, 9:31 AM

Also, $wgDisableAuthManager does not work.

This AuthManager news reads that you can override it. https://lists.wikimedia.org/pipermail/wikitech-l/2016-May/085725.html

AuthManager is currently behind a feature flag, $wgDisableAuthManager, which can be set to use the old authentication system rather than AuthManager.

Grep tells me that only extensions use it (ConfirmEdit, TitleBlacklist).

And MW 1.28 removes it again? https://www.mediawiki.org/wiki/MediaWiki_1.28/wmf.15/Changelog

Aklapper lowered the priority of this task from Unbreak Now! to Needs Triage.Sep 7 2016, 9:43 AM

Resetting bumped Priority value as per documentation.

A show stopper like this is not a blocker?

Subfader renamed this task from Log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki to AuthManager fails.Sep 7 2016, 10:07 AM

@Subfader: Don't know criteria for "show stopper" but if it's a recently introduced regression and thousands of wiki sites or millions of users are affected I could imagine this to be a "blocker". That does not seem to be the case currently.

Reverting to the previous and more specific task title ("XYZ doesn't work" is too vague). If you think the previous/current task title is incorrect, please elaborate why and how.

Aklapper renamed this task from AuthManager fails to Log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki.Sep 7 2016, 10:34 AM
Subfader renamed this task from Log-in fails with with 'invalid CSRF token error' on MS Windows on private wiki to AuthManager tokens don't match so HTML forms like login fail.Sep 7 2016, 10:47 AM
Anomie added a comment.Sep 7 2016, 2:13 PM

FYI, Phabricator has a "pastebin" which is a bit more convenient to use than a paste into a Flow post, or you can upload the log file as an actual upload.

Looking at what we have in that Flow post, this line

[cookie] already deleted setcookie: "DB27test_session", "", "1441642499", "/", "www.mysite.com", "", "1"

indicates that your browser did not send the session cookie along with the POST for some reason in the single submission you provided a log for.

In debugging this problem, it would be helpful if you could enable debugging for the storage backend, e.g. by placing this code into your LocalSettings.php:

$wgHooks['SetupAfterCache'][] = function () {
    global $wgSessionCacheType;
    ObjectCache::getInstance( $wgSessionCacheType )->setDebug( true );
};

Then capture the HTTP request and response headers for both loading Special:UserLogin and submitting it as well as the corresponding server logs. You might also include the headers and logs for requests in between the loading and the submitting, in case some other request in between is resetting the cookies.

Anomie added a comment.Sep 7 2016, 2:20 PM

Also, $wgDisableAuthManager does not work.

$wgDisableAuthManager was removed from 1.27 in the 1.27.0-rc.1 release candidate, and was removed from 1.28.0-alpha in 1.28.0-wmf.15 once translatewiki was ready for it.

The email you linked mentioned "we hope to be able to remove it entirely from 1.27 before release", which we were in fact able to do. If 1.27 hadn't been an LTS release we'd probably have left it in, but no one wanted to support both old and new authentication code until 2019.

Subfader added a comment.EditedSep 7 2016, 5:53 PM

<strike>I think I found it.</strike> I raised $wgAuthenticationTokenVersion to "2" right after the installation. Later while trying to debug I raised it even more.

I updated completely again and stumbled upon that.
The solution was to fall back to $wgAuthenticationTokenVersion = "1";

New bug? Raising $wgAuthenticationTokenVersion breaks logging in completely.

Anomie added a comment.Sep 7 2016, 5:59 PM

New bug? Raising $wgAuthenticationTokenVersion breaks logging in completely.

Can't reproduce, login works fine whether I set it to "1", "4", or "foobar".

Subfader added a comment.EditedSep 7 2016, 6:04 PM

I shot too fast. $wgAuthenticationTokenVersion = "1"; logged me in again. But in fact I cannot log out until I delete all cookies. Now I can't log in again like before.
Super annoying bug so far.

Anomie added a comment.Sep 7 2016, 6:18 PM

Check that the path and domain in the Set-Cookie headers actually matches the path and domain your wiki is on, and that if the "secure" flag is set that you're actually accessing the site via https. This is starting to sound very much like you set $wgCookiePath and/or $wgCookieDomain to values that don't match your actual site so the browser is ignoring the cookies.

Anomie added a comment.Sep 7 2016, 6:23 PM

Extended log as suggested: https://phabricator.wikimedia.org/P3994

This log again indicates that MediaWiki didn't receive the session cookie from the browser:

line 299
[cookie] already deleted setcookie: "DB27test_session", "", "1441735953", "/", "www.mysite.com", "", "1"
Subfader added a comment.EditedSep 7 2016, 7:49 PM

Not sure why there is a "forceHTTPS" cookie. I don't use HTTPS and have not enabled such variables.

I don't know how, but I think I escaped from that login hell now. Thanks Anomie!

Last thing I did was

  • being logged out > no cookies
  • going to Special:UserLogin > seeing cookies being set (?!)
  • Submit > error > cookies gone
  • browsing away
  • going to Special:UserLogin
  • deleting all cookies
  • Submit > success

This T147161 is related, since other users are having problems if they set CACHE_ACCEL

Paladox added a comment.EditedOct 3 2016, 7:37 PM

Try capturing the HTTP requests and responses for the entire login process, both loading Special:UserLogin and submitting it. It would also likely be helpful to capture debug-level logs from MediaWiki on at least the 'session', 'cookie', and 'authentication' channels.

How do you do that please?

(I use internet explorer, but I test in Microsoft Edge and chrome.)

Anomie added a comment.Oct 4 2016, 3:05 PM

To capture the requests and responses, a quick Google search turns up this useful-looking page for Microsoft Edge. You can repeat the process for whatever other browser you use.

To capture the debug-level logs, see mw:Manual:How_to_debug#Logging. You might also throw this into your LocalSettings.php to enable more logging from the storage backend.

$wgHooks['SetupAfterCache'][] = function () {
    global $wgSessionCacheType;
    ObjectCache::getInstance( $wgSessionCacheType )->setDebug( true );
};

Then redact any sensitive data (such as passwords) and create a paste or upload a .har file or whatever, and link it from a comment on this task.

Paladox added a comment.EditedOct 4 2016, 3:44 PM

@Anomie Hi thankyou,

Here you go

{P4154}

I only set it for you and tgr to see it for now, since I doint know if it includes private data.

But a quick search shows it doesn't include my password.

This

[session] User::loadFromSession called before the end of Setup.php
#0 /home/randomwi/public_html/en/includes/user/User.php(5120): User->load()
#1 /home/randomwi/public_html/en/includes/user/User.php(2763): User->loadOptions()
#2 /home/randomwi/public_html/en/extensions/BetaFeatures/includes/BetaFeaturesUtil.php(43): User->getOption(string)
#3 /home/randomwi/public_html/en/extensions/TimedMediaHandler/TimedMediaHandler.hooks.php(776): BetaFeatures::isFeatureEnabled(User, string)
#4 /home/randomwi/public_html/en/extensions/TimedMediaHandler/TimedMediaHandler.hooks.php(222): TimedMediaHandlerHooks::activeMode()
#5 [internal function]: TimedMediaHandlerHooks::register()
#6 /home/randomwi/public_html/en/includes/Setup.php(850): call_user_func(string)
#7 /home/randomwi/public_html/en/includes/WebStart.php(137): require_once(string)
#8 /home/randomwi/public_html/en/index.php(40): require(string)
#9 {main}

is done by https://gerrit.wikimedia.org/r/#/c/312327/

but the problem was happening before I did the patch, but not with that error.

Not sure how to fix that one, but it should not be causing the problem.

Anomie added a comment.Oct 4 2016, 4:37 PM

@Anomie Hi thankyou,
Here you go
P4154

It appears that you only included the logs of the actual attempt to log in, not the initial load of the login page or the HTTP requests and responses from the browser. But that is enough for me to see that the problem is that the session cookie isn't being sent by the browser in the post. Visiting your wiki's login page, I see it's sending the session cookie and deleting it in the same request.

Lines 149–174 look suspicious in that respect, why are there two other sessions loaded (and apparently attached to a WebRequest rather than a FauxRequest) that seem to have a need to save themselves at the end of the request?

This
[session] User::loadFromSession called before the end of Setup.php
#0 /home/randomwi/public_html/en/includes/user/User.php(5120): User->load()
#1 /home/randomwi/public_html/en/includes/user/User.php(2763): User->loadOptions()
#2 /home/randomwi/public_html/en/extensions/BetaFeatures/includes/BetaFeaturesUtil.php(43): User->getOption(string)
#3 /home/randomwi/public_html/en/extensions/TimedMediaHandler/TimedMediaHandler.hooks.php(776): BetaFeatures::isFeatureEnabled(User, string)
#4 /home/randomwi/public_html/en/extensions/TimedMediaHandler/TimedMediaHandler.hooks.php(222): TimedMediaHandlerHooks::activeMode()
#5 [internal function]: TimedMediaHandlerHooks::register()
#6 /home/randomwi/public_html/en/includes/Setup.php(850): call_user_func(string)
#7 /home/randomwi/public_html/en/includes/WebStart.php(137): require_once(string)
#8 /home/randomwi/public_html/en/index.php(40): require(string)
#9 {main}
is done by https://gerrit.wikimedia.org/r/#/c/312327/
but the problem was happening before I did the patch, but not with that error.
Not sure how to fix that one, but it should not be causing the problem.

Apparently not the current master of that patch, the line numbers don't match up. But there is no session in load.php, so you can't check if the session user has a beta feature enabled in the ResourceLoaderGetConfigVars hook. Use the MakeGlobalVariablesScript hook instead.

@Anomie thanks, I am not sure why it loads the session twice? Would you like me to generate the log when going to login page?

Also is this a bug?

@Anomie also there is no hook ResourceLoaderGetConfigVars in TimedMediaHandler, or in BetaFeatures too.

It's done on this line https://gerrit.wikimedia.org/r/#/c/312327/25/TimedMediaHandler.hooks.php@764

Anomie added a comment.Oct 4 2016, 5:14 PM

@Anomie thanks, I am not sure why it loads the session twice? Would you like me to generate the log when going to login page?
Also is this a bug?

It depends on why it's happening. You'll have to track that down before we know whether it's a bug and what the source of the bug is.

@Anomie also there is no hook ResourceLoaderGetConfigVars in TimedMediaHandler, or in BetaFeatures too.
It's done on this line https://gerrit.wikimedia.org/r/#/c/312327/25/TimedMediaHandler.hooks.php@764

At any rate, you're still trying to access the session in code executed from load.php. Figure out what that code is and work out how to not do that.

Paladox added a comment.EditedOct 4 2016, 5:21 PM

@Anomie it says this https://www.mediawiki.org/wiki/Manual:SessionManager_and_AuthManager/Updating_tips#Logged_warning_.22User::loadFromSession_called_before_the_end_of_Setup.php.22

But I doint know how I can add that to the code in TMH on line 764?

Also would getting the log for loading the login page help?

Since I doint think I know how to do this "It depends on why it's happening. You'll have to track that down before we know whether it's a bug and what the source of the bug is." On my own?

Paladox added a comment.EditedOct 4 2016, 5:26 PM

@Anomie Heres the debug log when loading the login page

{P4156}

Paladox added a comment.EditedOct 4 2016, 5:36 PM

@Anomie Strange it is now allowing me to login on Microsoft Edge.

But not google chrome.

Chrome debug

{P4157}

{P4158}

Paladox added a comment.EditedOct 4 2016, 7:27 PM

@Anomie It seems to have happened again after upgrading from mw 1.28 wmf 20 to wmf 21 it logged me out and I carn't log back in.

Caspervector added a subscriber: Caspervector.EditedApr 21 2017, 11:05 AM

I am also hit by this problem on MW v1.27.2. My wiki site that worked well with DEFAULT CHARSET=utf8 (for historical reasons; its DB was already up to date after using update.php) now denies all logins with a localised version of

There seems to be a problem with your login session; this action has been canceled as a precaution against session hijacking. Go back to the previous page, reload that page and then try again.

after I switched to DEFAULT CHARSET=binary in LocalSettings.php and converted the DB using the following statement on every table (except for searchindex) in the DB:

ALTER TABLE sometable CONVERT TO CHARACTER SET binary;

This issue is reproducible on my wiki even with incorrect (username, password) combinations; viewing and searching seem to work as expected, but editing cannot be tested because of permission settings on my wiki. Attached is the log of a login attempt after setting $wgDebugLogFile and appending Anomie's debugging snippet to LocalSettings.php.

Attached is the log of a login attempt after setting $wgDebugLogFile and appending Anomie's debugging snippet to LocalSettings.php.

Unfortunately SqlBagOStuff apparently doesn't log set attempts, so we can't see where it tries to save, and while it does log misses it doesn't log the missed key. But it does look like the problem is that either your data isn't being saved to the database, or it's being deleted somewhere, or it's being corrupted so it can't be successfully read back in on load.

Caspervector added a comment.EditedApr 22 2017, 4:58 AM

Well, please feel free to ask for more information if necessary. I have set up a test VM with the data from my wiki, and can switch between the binary and utf8 versions very easily. I can confirm that the exact difference between the two versions is the changed DEFAULT CHARSET plus the CONVERT TO CHARACTER SET conversions.

Caspervector added a comment.EditedApr 22 2017, 5:02 AM

Sorry but I previously forgot to mention in my two comments that there is an additional operation on the DB before the CONVERT TO CHARACTER SET conversions:

ALTER DATABASE wiki CHARACTER SET binary;
Anomie added a comment.EditedApr 24 2017, 3:12 PM

You'll likely want to add more logging into SqlBagOStuff (as a local hack on your local wiki) to get a better idea of where exactly things are going wrong.

Unfortunately I am not familiar with with the MediaWiki codebase at all. Would you please provide some examples? Thanks...

Caspervector added a comment.EditedMay 4 2017, 1:56 AM

I debugged this yesterday. Since the get: no matching rows warning is from getMulti() in SqlBagOStuff.php, I modified the statement that prints this warning to also emit the search key. Comparing the logs of both utf8 and binary versions, I found the first key that resulted in get: no matching rows to be actually present in the objectcache table, but the keyname is the search key concatenated with \0s.

After closer inspection, I found the type of keyname to be binary(255) because of CONVERT TO CHARACTER SET (plus it being char(255) binary originally), but it should be varbinary(255). So the culprit for my issue is schema mismatch; I then converted the utf8 version manually (actually using some automation, but without using CONVERT TO CHARACTER SET on whole tables) according to the correct schema, and found everything to be OK now.