Page MenuHomePhabricator

[EmailAuth] RuntimeException: CAS update failed on user_touched. The version of the user to be saved is older than the current version.
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
  • service.version: 1.46.0-wmf.2
  • timestamp: 2025-11-20T15:26:42.481Z
  • labels.phpversion: 8.3.26
  • trace.id: 71b861a4-9212-4bf9-8e91-c4e800f971c1
  • Find trace.id in Logstash
labels.normalized_message
[{reqId}] {exception_url}   RuntimeException: CAS update failed on user_touched. The version of the user to be saved is older than the current version.
FrameLocationCall
from/srv/mediawiki/php-1.46.0-wmf.2/includes/User/User.php(2361)
#0/srv/mediawiki/php-1.46.0-wmf.2/includes/libs/Rdbms/Database/Database.php(2323)MediaWiki\User\User->MediaWiki\User\{closure}(Wikimedia\Rdbms\DatabaseMySQL, string)
#1/srv/mediawiki/php-1.46.0-wmf.2/includes/libs/Rdbms/Database/DBConnRef.php(127)Wikimedia\Rdbms\Database->doAtomicSection(string, Closure)
#2/srv/mediawiki/php-1.46.0-wmf.2/includes/libs/Rdbms/Database/DBConnRef.php(764)Wikimedia\Rdbms\DBConnRef->__call(string, array)
#3/srv/mediawiki/php-1.46.0-wmf.2/includes/User/User.php(2335)Wikimedia\Rdbms\DBConnRef->doAtomicSection(string, Closure)
#4/srv/mediawiki/php-1.46.0-wmf.2/extensions/EmailAuth/includes/EmailAuthSecondaryAuthenticationProvider.php(104)MediaWiki\User\User->saveSettings()
#5/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/MWCallableUpdate.php(52)MediaWiki\Extension\EmailAuth\EmailAuthSecondaryAuthenticationProvider::MediaWiki\Extension\EmailAuth\{closure}(string)
#6/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdates.php(445)MediaWiki\Deferred\MWCallableUpdate->doUpdate()
#7/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdates.php(187)MediaWiki\Deferred\DeferredUpdates::attemptUpdate(MediaWiki\Deferred\MWCallableUpdate)
#8/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdates.php(274)MediaWiki\Deferred\DeferredUpdates::run(MediaWiki\Deferred\MWCallableUpdate)
#9/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdatesScope.php(229)MediaWiki\Deferred\DeferredUpdates::MediaWiki\Deferred\{closure}(MediaWiki\Deferred\MWCallableUpdate, int)
#10/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdatesScope.php(158)MediaWiki\Deferred\DeferredUpdatesScope->processStageQueue(int, int, Closure)
#11/srv/mediawiki/php-1.46.0-wmf.2/includes/Deferred/DeferredUpdates.php(268)MediaWiki\Deferred\DeferredUpdatesScope->processUpdates(int, Closure)
#12/srv/mediawiki/php-1.46.0-wmf.2/includes/MediaWikiEntryPoint.php(656)MediaWiki\Deferred\DeferredUpdates::doUpdates()
#13/srv/mediawiki/php-1.46.0-wmf.2/includes/MediaWikiEntryPoint.php(478)MediaWiki\MediaWikiEntryPoint->restInPeace()
#14/srv/mediawiki/php-1.46.0-wmf.2/includes/MediaWikiEntryPoint.php(436)MediaWiki\MediaWikiEntryPoint->doPostOutputShutdown()
#15/srv/mediawiki/php-1.46.0-wmf.2/includes/MediaWikiEntryPoint.php(193)MediaWiki\MediaWikiEntryPoint->postOutputShutdown()
#16/srv/mediawiki/php-1.46.0-wmf.2/index.php(44)MediaWiki\MediaWikiEntryPoint->run()
#17/srv/mediawiki/w/index.php(3)require(string)
#18{main}
Notes

I see 9118 of these in the last 3 weeks. They appear to spike starting in 1.46.0-wmf.1 (T408271):

Screenshot 2025-11-20 at 09-38-52 MediaWiki New Errors ECS - OpenSearch Dashboards.png (258×636 px, 23 KB)

This increase was probably missed in log triage because of an existing filter on the MediaWiki New Errors ECS dashboard for T386205.

Event Timeline

All CAS errors are similar to all other CAS errors inasmuch as they are CAS errors, but that's not really helpful in practice. The EmailAuth one seems to be the dominant error since Nov 7 or so:

Screenshot Capture - 2025-11-22 - 18-00-50.png (687×2 px, 82 KB)

The corresponding log message (why is that sent to the preferences channel? anyway...) says these are all replica reads. AuthManager should probably pass a primary User instance to the authentication providers...

The deferred code is from T390506: EmailAuth: Allow functionality for users with unconfirmed emails but it hasn't been touched in months, and AuthManager rarely changes, so not sure why this started happening now.

It's a deferred, so not the end of the world (the user just ends up not being email-confirmed after a successful email verification (@kostajh FYI)). But it would be nice to fix, and to understand what triggered it.

AuthManager should probably pass a primary User instance to the authentication providers...

It actually does. The request in which the user gets created uses the User instance that User::addToDatabase() was called on, which is effectively a primary account (although not explicitly marked as such, which is why the log is confusing); and further requests explicitly load from the primary.

Change #1213109 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/core@master] user: Mark users created with User::addToDatabase() as primary

https://gerrit.wikimedia.org/r/1213109

Change #1213109 merged by jenkins-bot:

[mediawiki/core@master] user: Mark users created with User::addToDatabase() as primary

https://gerrit.wikimedia.org/r/1213109

Change #1214041 had a related patch set uploaded (by D3r1ck01; author: Gergő Tisza):

[mediawiki/core@wmf/1.46.0-wmf.4] user: Mark users created with User::addToDatabase() as primary

https://gerrit.wikimedia.org/r/1214041

Change #1214041 merged by jenkins-bot:

[mediawiki/core@wmf/1.46.0-wmf.4] user: Mark users created with User::addToDatabase() as primary

https://gerrit.wikimedia.org/r/1214041

Mentioned in SAL (#wikimedia-operations) [2025-12-02T14:21:39Z] <derick@deploy2002> Started scap sync-world: Backport for [[gerrit:1214041|user: Mark users created with User::addToDatabase() as primary (T410652)]]

Mentioned in SAL (#wikimedia-operations) [2025-12-02T14:25:24Z] <derick@deploy2002> d3r1ck01, derick: Backport for [[gerrit:1214041|user: Mark users created with User::addToDatabase() as primary (T410652)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.

Mentioned in SAL (#wikimedia-operations) [2025-12-02T14:30:13Z] <derick@deploy2002> Finished scap sync-world: Backport for [[gerrit:1214041|user: Mark users created with User::addToDatabase() as primary (T410652)]] (duration: 08m 34s)

Change #1214132 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):

[mediawiki/extensions/EmailAuth@master] Update user object from primary DB instead of replica

https://gerrit.wikimedia.org/r/1214132

I've monitored Logstash since the deployment, but it hasn't gone down. These lines up accurately with https://logstash.wikimedia.org/goto/71373cec585746d63094e22d911053b4 (CAS update failed on user_touched for user ID '{user_id}' ({db_flag} read)), which are all coming from replica DBs.

The DB flag is set to replica, which means the user object that we're dealing with is coming from a replica DB. We will need to fetch an instance of the user object from the primary DB before trying to apply the settings. I made: https://gerrit.wikimedia.org/r/c/mediawiki/extensions/EmailAuth/+/1214132/.

Change #1214154 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):

[mediawiki/extensions/EmailAuth@master] Add debug logging for T410652

https://gerrit.wikimedia.org/r/1214154

Change #1214533 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):

[mediawiki/core@master] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214533

Change #1214533 merged by jenkins-bot:

[mediawiki/core@master] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214533

Change #1214620 had a related patch set uploaded (by D3r1ck01; author: Bartosz Dziewoński):

[mediawiki/core@wmf/1.46.0-wmf.4] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214620

Change #1214621 had a related patch set uploaded (by D3r1ck01; author: Bartosz Dziewoński):

[mediawiki/core@wmf/1.46.0-wmf.5] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214621

Change #1214620 merged by jenkins-bot:

[mediawiki/core@wmf/1.46.0-wmf.4] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214620

Change #1214621 merged by jenkins-bot:

[mediawiki/core@wmf/1.46.0-wmf.5] User: Log where the data was loaded when CAS update failed

https://gerrit.wikimedia.org/r/1214621

Mentioned in SAL (#wikimedia-operations) [2025-12-03T21:34:59Z] <derick@deploy2002> Started scap sync-world: Backport for [[gerrit:1214620|User: Log where the data was loaded when CAS update failed (T410652)]], [[gerrit:1214621|User: Log where the data was loaded when CAS update failed (T410652)]]

Mentioned in SAL (#wikimedia-operations) [2025-12-03T21:37:49Z] <derick@deploy2002> derick, d3r1ck01: Backport for [[gerrit:1214620|User: Log where the data was loaded when CAS update failed (T410652)]], [[gerrit:1214621|User: Log where the data was loaded when CAS update failed (T410652)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.

Mentioned in SAL (#wikimedia-operations) [2025-12-03T21:42:32Z] <derick@deploy2002> Finished scap sync-world: Backport for [[gerrit:1214620|User: Log where the data was loaded when CAS update failed (T410652)]], [[gerrit:1214621|User: Log where the data was loaded when CAS update failed (T410652)]] (duration: 07m 33s)

Logs after deployment shows:

from /srv/mediawiki/php-1.46.0-wmf.4/includes/User/User.php(491)
#0 /srv/mediawiki/php-1.46.0-wmf.4/includes/User/User.php(447): MediaWiki\User\User->loadFromId(int)
#1 /srv/mediawiki/php-1.46.0-wmf.4/includes/User/User.php(1493): MediaWiki\User\User->load()
#2 /srv/mediawiki/php-1.46.0-wmf.4/includes/User/User.php(2080): MediaWiki\User\User->getId()
#3 /srv/mediawiki/php-1.46.0-wmf.4/includes/Auth/AuthManager.php(727): MediaWiki\User\User->isRegistered()
#4 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/AuthManagerSpecialPage.php(415): MediaWiki\Auth\AuthManager->continueAuthentication(array)
#5 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/AuthManagerSpecialPage.php(548): MediaWiki\SpecialPage\AuthManagerSpecialPage->performAuthenticationStep(string, array)
#6 /srv/mediawiki/php-1.46.0-wmf.4/includes/HTMLForm/HTMLForm.php(812): MediaWiki\SpecialPage\AuthManagerSpecialPage->handleFormSubmit(array, MediaWiki\HTMLForm\CodexHTMLForm)
#7 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/AuthManagerSpecialPage.php(479): MediaWiki\HTMLForm\HTMLForm->trySubmit()
#8 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/LoginSignupSpecialPage.php(395): MediaWiki\SpecialPage\AuthManagerSpecialPage->trySubmit()
#9 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/SpecialPage.php(711): MediaWiki\SpecialPage\LoginSignupSpecialPage->execute(null)
#10 /srv/mediawiki/php-1.46.0-wmf.4/includes/SpecialPage/SpecialPageFactory.php(1743): MediaWiki\SpecialPage\SpecialPage->run(null)
#11 /srv/mediawiki/php-1.46.0-wmf.4/includes/Actions/ActionEntryPoint.php(499): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, MediaWiki\Context\RequestContext)
#12 /srv/mediawiki/php-1.46.0-wmf.4/includes/Actions/ActionEntryPoint.php(143): MediaWiki\Actions\ActionEntryPoint->performRequest()
#13 /srv/mediawiki/php-1.46.0-wmf.4/includes/MediaWikiEntryPoint.php(184): MediaWiki\Actions\ActionEntryPoint->execute()
#14 /srv/mediawiki/php-1.46.0-wmf.4/index.php(44): MediaWiki\MediaWikiEntryPoint->run()
#15 /srv/mediawiki/w/index.php(3): require(string)
#16 {main}

Hm. I thought AuthManager makes sure it is a primary user but I must have misread the code because for login it acutally doesn't. I suppose there isn't really a strong reason to, most authentication providers wouldn't change user data on login.

Hm. I thought AuthManager makes sure it is a primary user but I must have misread the code because for login it acutally doesn't. I suppose there isn't really a strong reason to, most authentication providers wouldn't change user data on login.

Yes, you're correct, and for the few cases like email confirmation that do DB writes (on GET requests) during login, we have to handle those separately.

Change #1215113 had a related patch set uploaded (by D3r1ck01; author: D3r1ck01):

[mediawiki/core@master] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215113

Change #1214154 abandoned by D3r1ck01:

[mediawiki/extensions/EmailAuth@master] Add debug logging for T410652

Reason:

No longer needed.

https://gerrit.wikimedia.org/r/1214154

Change #1215113 merged by jenkins-bot:

[mediawiki/core@master] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215113

Change #1214132 merged by jenkins-bot:

[mediawiki/extensions/EmailAuth@master] Fetch user object from primary DB (for writes) not replica DB

https://gerrit.wikimedia.org/r/1214132

Change #1215165 had a related patch set uploaded (by D3r1ck01; author: D3r1ck01):

[mediawiki/core@wmf/1.46.0-wmf.5] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215165

Change #1215166 had a related patch set uploaded (by D3r1ck01; author: D3r1ck01):

[mediawiki/core@wmf/1.46.0-wmf.4] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215166

Change #1215167 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):

[mediawiki/extensions/EmailAuth@wmf/1.46.0-wmf.5] Fetch user object from primary DB (for writes) not replica DB

https://gerrit.wikimedia.org/r/1215167

Change #1215165 merged by jenkins-bot:

[mediawiki/core@wmf/1.46.0-wmf.5] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215165

Change #1215166 merged by jenkins-bot:

[mediawiki/core@wmf/1.46.0-wmf.4] Revert "User: Log where the data was loaded when CAS update failed"

https://gerrit.wikimedia.org/r/1215166

Change #1215167 merged by jenkins-bot:

[mediawiki/extensions/EmailAuth@wmf/1.46.0-wmf.5] Fetch user object from primary DB (for writes) not replica DB

https://gerrit.wikimedia.org/r/1215167

Mentioned in SAL (#wikimedia-operations) [2025-12-04T14:23:50Z] <derick@deploy2002> Started scap sync-world: Backport for [[gerrit:1215165|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215166|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215167|Fetch user object from primary DB (for writes) not replica DB (T410652)]]

Mentioned in SAL (#wikimedia-operations) [2025-12-04T14:26:07Z] <derick@deploy2002> d3r1ck01, derick: Backport for [[gerrit:1215165|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215166|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215167|Fetch user object from primary DB (for writes) not replica DB (T410652)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes

Mentioned in SAL (#wikimedia-operations) [2025-12-04T14:37:14Z] <derick@deploy2002> Finished scap sync-world: Backport for [[gerrit:1215165|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215166|Revert "User: Log where the data was loaded when CAS update failed" (T410652)]], [[gerrit:1215167|Fetch user object from primary DB (for writes) not replica DB (T410652)]] (duration: 13m 24s)

After deploying the backport of I49fcec68427b70f (f674fc54418b9b2de5a) and monitoring the logs, the issue is no longer occurring after 14:35:30 (last occurrence): https://logstash.wikimedia.org/goto/0343934111dcac6d80b17f749494aa1b

Screenshot 2025-12-04 at 5.55.13 PM.png (534×1 px, 73 KB)

This can be resolved now!

DAlangi_WMF renamed this task from RuntimeException: CAS update failed on user_touched. The version of the user to be saved is older than the current version. to [EmailAuth] RuntimeException: CAS update failed on user_touched. The version of the user to be saved is older than the current version..Thu, Dec 4, 4:56 PM