Page MenuHomePhabricator

Locking hundreds of accounts with Special:MultiLock results in 0 locks
Closed, ResolvedPublicBUG REPORT

Description

Steps to replicate the issue (include links if applicable):

  • Try to lock ~200 accounts at the same time using Special:MultiLock

What happens?:
You get a bunch of green checkmarks, and log entries are made for each account, but no accounts are locked.

What should have happened instead?:
Either an error message tellimg me I can't do that, or the accounts being locked.

Software version (on Special:Version page; skip for WMF-hosted wikis like Wikipedia):

Other information (browser name/version, screenshots, etc.):
A batch of 100 accounts worked.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Reedy triaged this task as High priority.Mar 23 2025, 7:42 PM

Is it specifically <= 100 that works? Or does 101 work?

I suspect the 100 working may be slightly arbitrary...

The search does limit to find 100 users, but I'm guessing that number was picked fairly arbitrarily too... And again, irrelevant to this.

There's presumably not some replag component to this, right?

I suspect the 100 working may be slightly arbitrary...

Agreed. I tried the full list of accounts, and got a single error. Then I split it into 500-account blocks, saw the green checkmarks, and didn't notice any problems until I finished and was looking closer at the accounts list. Then I tried a block of 200, that didn't work, so I went to 100. There was an hour between the 500-block attempt and the block of 200, then 10 minutes between the block of 200 and the first block of 100.

It's odd, because Special:MultiLock is just a foreach loop over the same function that Special:CentralAuth uses. So if there was something slow or timing out or whatever I'd expect at least the first account to get locked, but that didn't happen.

I've read the code and there isn't anything obvious in it that would cause this. It could be some less obvious problem with one of the many levels of caching of CentralAuthUser objects.

Are we positive that the accounts were not locked? One scenario I can imagine is that the locking succeeded, the page showed success messages, but below them it showed outdated information in the table saying that the users were not locked while in fact they were.

Trust and Safety Product Team are you interested in picking up this work?

I'm not sure we would have the space for it at the moment (from an engineering point of view). Perhaps others can speak to that though.

Ideally I'd like to see T373388: Replace CentralAuth account locks with GlobalBlocking global blocks be worked on (which would remove this special page), but I'm not sure we have space for that either at the moment and that task will be a lot more work.

Are we positive that the accounts were not locked? One scenario I can imagine is that the locking succeeded, the page showed success messages, but below them it showed outdated information in the table saying that the users were not locked while in fact they were.

Yes, I checked a couple of accounts individually in Special:CentralAuth, both at the top of the list and in the middle, an hour after doing the batches of 500. When I tried the batch of 200, the table showed them not locked and the mark-locked script did not show them as locked. When I did the batches of 100 ten minutes later, they showed as unlocked when I loaded the batch and locked after running, both in the table and with the mark-locked script.

It could be some less obvious problem with one of the many levels of caching of CentralAuthUser objects.

Ref: T380500: CentralAuthUser returning outdated data after user creation
Doesn't fit the symptoms here well IMO, but it's a possibility.

I just noticed a new series of locks that might have suffered from the same issue: https://meta.wikimedia.org/w/index.php?title=Steward_requests/Global&oldid=28477542#Global_lock_for_more_socks_of_Ricardinho_da_Souza_Silva_7.

For the record: I noticed that I could manually re-lock this account.

I've tested the bug with LTA sockpuppets. Locking 153 accounts at 17:13 UTC using Special:MultiLock showed green checkmarks and created lock entries, but the accounts weren't actually locked: https://meta.wikimedia.org/w/index.php?title=Special:Log/Johannnes89&type=&user=Johannnes89&offset=20250402184315%7C59345236&limit=153

Tried again with 120 accounts at 18:43 UTC – same result: https://meta.wikimedia.org/w/index.php?title=Special:Log/Johannnes89&type=&user=Johannnes89&offset=20250402184613%7C59345375&limit=120

Same with 101 accounts at 18:46:14 – 18:46:16 UTC : https://meta.wikimedia.org/w/index.php?title=Special:Log/Johannnes89&type=&user=Johannnes89&offset=20250402184645%7C59345478&limit=101

Finally using MultiLock with 100 accounts worked at 18:46:45 – 18:46:48 (didn't want to wait any longer): https://meta.wikimedia.org/w/index.php?title=Special:Log/Johannnes89&type=&user=Johannnes89&dir=prev&offset=20250402184616%7C59345477&limit=100 – see e.g. https://meta.wikimedia.org/w/index.php?title=Special:CentralAuth&target=44x9280827 with 4 lock entries, only the fourth attempt actually locked the account.

Thank you for testing that @Johannnes89. Just to be super sure, I checked the lock status in the globaluser table and indeed out of those 153 names, only 100 are locked right now.

I tested this locally, creating 120 accounts with createAndPromote.php and locking them with Special:MultiLock. In my test all 120 locks succeeded (checked with a query on the globaluser table), but the table showed that only 8 of them were locked. So I guess we have more than one problem…

I still don't see anything that would cause this. The limit of 100 is used in SpecialMultiLock.php, but only for the search for usernames with a prefix. It is also the size of the process-local cache in CentralAuthUserCache.php.

I guess the next step is for me to try the same thing on the beta cluster, hoping that it reproduces there, with debug logging enabled; and then if that fails, then to try it in production.

I tried on the beta cluster, and did not reproduce – all 120 accounts got locked.

I'm now reviewing the debug logs. One weird thing I noticed is that we are calling CentralAuthUser::saveSettings 3 times for every locked account. One of the fields written by that method is gu_locked. On the beta cluster, the field is correctly set to '1', but maybe in production this is somehow restoring the old value of '0' and thus undoing the lock.

I tried on the beta cluster, and did not reproduce – all 120 accounts got locked.

I'm now reviewing the debug logs. One weird thing I noticed is that we are calling CentralAuthUser::saveSettings 3 times for every locked account. One of the fields written by that method is gu_locked. On the beta cluster, the field is correctly set to '1', but maybe in production this is somehow restoring the old value of '0' and thus undoing the lock.

Does it do any extra reads? From cache and/or a replica?

Sure, about 7 times per locked user… but I'm not sure how to tell if they're reading from master or replica. Probably master? edit: The queries are all to deployment-db11, which is the master.

What I'd like to do next:

  • Add debug logging to CentralAuthUser::saveSettings to log the stack trace, spl_object_id(), and the gu_locked value it's saving
  • Add debug logging to CentralAuthUser::loadFromDatabase to log the stack trace, spl_object_id(), and the gu_locked value it loaded
  • Change the limit of 100 in CentralAuthUserCache to something that makes debugging easier and less noisy, perhaps 3
  • Deploy these changes to mwdebug and test a multi-lock in production

I'll come back to this tomorrow.

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

[mediawiki/extensions/CentralAuth@master] Temporary debugging code for T389728

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

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

[mediawiki/extensions/CentralAuth@wmf/1.44.0-wmf.23] Temporary debugging code for T389728

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

Change #1133868 abandoned by Bartosz Dziewoński:

[mediawiki/extensions/CentralAuth@wmf/1.44.0-wmf.23] Temporary debugging code for T389728

Reason:

Testing done, no longer needed

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

Change #1133866 abandoned by Bartosz Dziewoński:

[mediawiki/extensions/CentralAuth@master] Temporary debugging code for T389728

Reason:

Testing done, no longer needed

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

We've pulled the above patch on mwdebug1001, and I did the test again, attempting to lock 5 of my old test accounts (with cache size set to 3, which should reproduce the issue): https://meta.wikimedia.org/wiki/Special:Log?type=globalauth&user=Bartosz+Dziewoński+(WMF)

And indeed, the log entries were created, but the accounts are not locked.

The relevant debug logs are recorded here: https://logstash.wikimedia.org/goto/626694484335f03ffae1c3ea4be0c09b I haven't finished reviewing them yet.

I am pretty sure that the fault lies in CentralAuthIdLookup::lookupUserNamesWithLocalFilter (added in https://gerrit.wikimedia.org/r/c/mediawiki/extensions/CentralAuth/+/1121128).

187:		$fromPrimaryDb = $this->shouldUsePrimary( $flags );
...
228:		$db = $this->databaseManager->getCentralDBFromRecency( $flags );
229:		$res = $db->newSelectQueryBuilder()->...->fetchResultSet();
...
235:		foreach ( $res as $row ) {
236:			$centralUser = CentralAuthUser::newFromRow( $row, [], $fromPrimaryDb );
237:			$this->userCache->set( $centralUser );

When that method is called with $flags == 0 (reading from replica), we create a $db object pointing to a replica database, but the $fromPrimaryDb boolean may reflect the use of the primary database, because shouldUsePrimary() also checks $this->databaseManager->centralLBHasRecentPrimaryChanges(). Next, when we create the CentralAuthUser object, we assume that these two values match, but they may not, in which case we will store an object in CentralAuthUserCache that thinks it was loaded from primary, but was actually loaded from replica. Then, when some other code fetches this object from the cache and calls saveSettings() on it, it will write the outdated values back into the primary database.

I'm not sure whether we should change $db or $fromPrimaryDb in this code, but either should fix the issue.

Separately, we should probably also change CentralAuthUser::adminLock() and other similar methods to use a "CAS token" (compare-and-swap?) in the same way as saveSettings() does, which should let us detect bugs where we try to write outdated values from saveSettings() later, to prevent this kind of issues in the future even if we cache the wrong data.


The key observation from the debug logs was the fact that this entry:

Apr 3, 2025 @ 14:25:55.124	CentralAuth	T389728 saveSettings called for object=2165 user=Matma Rex test 2020-03-03 locked=0

…was a save on a new CentralAuthUser object (indicated by object=2165, which hasn't appeared in earlier log entries), and it was not preceded by any log entries about loading the CentralAuthUser object (neither Loading state for global user {user} from DB nor Loading CentralAuthUser for user {user} from cache object), was not preceded by a warning like Write mode called on replica-loaded object, but it was preceded by this one:

Apr 3, 2025 @ 14:25:55.110	rdbms	MediaWiki\Extension\CentralAuth\User\CentralAuthIdLookup::lookupUserNamesWithLocalFilter [0.755ms] db1181: SELECT  gu_id,gu_name,lu_wiki,ln_wiki,gu_password,gu_auth_token,gu_locked,gu_hidden_level,gu_registration,gu_email,gu_email_authenticated,gu_home_db,gu_cas_token  FROM `globaluser` LEFT JOIN `localuser` ON ((gu_name=lu_name) AND lu_wiki = 'metawiki') LEFT JOIN `localnames` ON ((gu_name=ln_name) AND ln_wiki = 'metawiki')   WHERE gu_name = 'Matma Rex test 2020-03-03'

…which reads all the data you need for a CentralAuthUser object from a replica database db1181, rather than the primary database db1236 (see https://noc.wikimedia.org/db.php).

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

[mediawiki/extensions/CentralAuth@master] CentralAuthIdLookup: Use primary DB more consistently

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

Change #1135119 merged by jenkins-bot:

[mediawiki/extensions/CentralAuth@master] CentralAuthIdLookup: Use primary DB more consistently

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

The fix will be deployed to Wikimedia wikis next week on the usual schedule. I'm sorry, I don't think I'll have the time this week for doing backports or additional testing.

Separately, we should probably also change CentralAuthUser::adminLock() and other similar methods to use a "CAS token" (compare-and-swap?) in the same way as saveSettings() does, which should let us detect bugs where we try to write outdated values from saveSettings() later, to prevent this kind of issues in the future even if we cache the wrong data.

Filed as T391491.