Page MenuHomePhabricator

MediaWiki deadlock when multiple files of same SHA1 are deleted simultaneously
Open, Needs TriagePublic

Description

This was observed in https://commons.wikimedia.org/wiki/User_talk:Zhuyifei1999#Embedded_Data_Bot_and_a_race_condition (the bot is for T129845)

The relevant logs on pywikibot's side:

Executing delete on [[commons:File:Copie de Copie de Copie de Copie de 001 Breaking And Bad 29.png]]
Sleeping for 0.8 seconds, 2018-06-12 17:00:13
WARNING: API error lockmanager-fail-acquirelock: Could not acquire lock for "mwstore://local-multiwrite/local-deleted/m/c/z/mczsju0t6qf7cm0a3qf6ylct0dh93bg.png".
API Error: query=
u"{u'maxlag': ['5'], 'title': [FilePage(File:Copie de Copie de Copie de Copie de 001 Breaking And Bad 29.png)], u'format': [u'json'], 'reason': [u'This file contains [[COM:CSD#F9', u'embedded data]]: After 145.6KiB (149053 bytes, via Ending,Magic): Identified type: application/x-rar (RAR archive data, v4, os: Win32)'], u'assert': [u'user'], 'token': [u'REDACTED+\\\\'], 'action': [u'delete']}"
           response=
{u'servedby': u'mw1344', u'error': {u'info': u'Could not acquire lock for "mwstore://local-multiwrite/local-deleted/m/c/z/mczsju0t6qf7cm0a3qf6ylct0dh93bg.png".', u'code': u'lockmanager-fail-acquirelock', u'help': u'See https://commons.wikimedia.org/w/api.php for API usage. Subscribe to the mediawiki-api-announce mailing list at <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> for notice of API deprecations and breaking changes.'}}
WARNING: Failed API request on attempt 0
Sleeping for 0.7 seconds, 2018-06-12 17:00:14
WARNING: API error internal_api_error_LocalFileLockError: [Wx-8HwpAEDEAACTVNM0AAAAH] Exception caught: Could not acquire lock for "mwstore://local-multiwrite/local-public/7/76/Copie_de_Copie_de_Copie_de_Copie_de_001_Breaking_And_Bad_29.png".
ERROR: Detected MediaWiki API exception internal_api_error_LocalFileLockError: [Wx-8HwpAEDEAACTVNM0AAAAH] Exception caught: Could not acquire lock for "mwstore://local-multiwrite/local-public/7/76/Copie_de_Copie_de_Copie_de_Copie_de_001_Breaking_And_Bad_29.png". [servedby:mw1284]; raising
MediaWiki exception LocalFileLockError details:
          query=
u"{u'maxlag': ['5'], 'title': [FilePage(File:Copie de Copie de Copie de Copie de 001 Breaking And Bad 29.png)], u'format': [u'json'], 'reason': [u'This file contains [[COM:CSD#F9', u'embedded data]]: After 145.6KiB (149053 bytes, via Ending,Magic): Identified type: application/x-rar (RAR archive data, v4, os: Win32)'], u'assert': [u'user'], 'token': [u'REDACTED+\\\\'], 'action': [u'delete']}"
          response=
{u'servedby': u'mw1284', u'error': {u'info': u'[Wx-8HwpAEDEAACTVNM0AAAAH] Exception caught: Could not acquire lock for "mwstore://local-multiwrite/local-public/7/76/Copie_de_Copie_de_Copie_de_Copie_de_001_Breaking_And_Bad_29.png".', u'code': u'internal_api_error_LocalFileLockError'}}
WARNING: Failed API request on attempt 1

AFAICT, the deletion hash is calculated by sha, so if multiple files with the same sha are being deleted at the exact same time, the move target uri gets locked by one of the deletions and end up successful. The other deletion fail to lock the target, but locks the source without unlocking it (till the TTL expires, default = 2 hours).

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

For web requests, the lock timeout should be 5 min:

$met = ini_get( 'max_execution_time' ); // this is 0 in CLI mode
$this->lockTTL = max( 5 * 60, 2 * (int)$met );

Also, onTransactionResolution() is set by LocalFile::lock() to release the lock on COMMIT or ROLLBACK (exceptions trigger the later), so I'm not sure why any lock would persist after one request failed with a lock exception. The LockManager destructor also does this.

If it was a fatal PHP error, then a dangling lock is possible.

I'm not sure about the internals, but the first lock error is lockmanager-fail-acquirelock and the second is internal_api_error_LocalFileLockError. Could it be something going on with multiple different locks handled by different routines?

Vvjjkkii renamed this task from MediaWiki deadlock when multiple files of same SHA1 are deleted simultaneously to m3aaaaaaaa.Jul 1 2018, 1:04 AM
Vvjjkkii triaged this task as High priority.
Vvjjkkii updated the task description. (Show Details)
Vvjjkkii removed a subscriber: Aklapper.
CommunityTechBot renamed this task from m3aaaaaaaa to MediaWiki deadlock when multiple files of same SHA1 are deleted simultaneously.Jul 2 2018, 1:53 PM
CommunityTechBot raised the priority of this task from High to Needs Triage.
CommunityTechBot updated the task description. (Show Details)
CommunityTechBot added a subscriber: Aklapper.

Encountered this error on testwiki today. Error code is lockmanager-fail-acquirelock and error text is something like Could not acquire lock for "mwstore://local-multiwrite/local-deleted/f/a/e/fae7og4zcjppicvqojoaqgnkl8mzl6j.png".

jcrespo subscribed.

Adding parent task- while this is not a strict subtask, this tracking task is so related (potentially solving sha1 management issues) that I think is relevant to put it under it.