Page MenuHomePhabricator

Unable to delete file pages on commons: MWException/LocalFileLockError: "Could not acquire lock"
Open, Stalled, HighPublic

Description

Unable to delete pages on commons:

April 4:

April 18:

May 7:

Related Objects

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
matmarex updated the task description. (Show Details)May 7 2016, 7:14 PM

Yet a other one: https://commons.wikimedia.org/wiki/File:Eden_rojas5.jpg

API request failed (internal_api_error_LocalFileLockError): [Vy5A4gpAID4AACu8Q5QAAACN] Exception Caught: Could not acquire lock for 'Eden_rojas5.jpg.'
Steinsplitter added a comment.EditedMay 7 2016, 7:31 PM

And a other one: https://commons.wikimedia.org/wiki/File:CA%C3%93TICA.jpg

API request failed (internal_api_error_LocalFileLockError): [Vy5CMApAEH8AACC9TPIAAABE] Exception Caught: Could not acquire lock for 'CAÓTICA.jpg.'

This is very disturbing when working on deletion requests. Adding them here for tracking.

And:

jcrespo added a subscriber: jcrespo.May 9 2016, 7:35 AM

I wanted to discard data drift between servers (an issue I found before), I think I did:

$ mysql -BN -A -h db1040 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -
$ mysql -BN -A -h db1042 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -
$ mysql -BN -A -h db1056 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -
$ mysql -BN -A -h db1059 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -
$ mysql -BN -A -h db1064 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -
$ mysql -BN -A -h db1068 commonswiki -e "SELECT * FROM page where page_namespace=6 AND page_title='(1)_Piano_Recital_at_12.jpg';SELECT * FROM revision WHERE rev_page=48412604;SELECT * FROM image WHERE img_name='(1)_Piano_Recital_at_12.jpg'" | md5sum
ae9297a9b9c1ca94733ccdb1a90ecd06  -

From the infrastructure point of view, it looks as if the file was actually successful deleted, but the database wasn't updated to reflect this. I will leave the why to the mediawiki people, and offer help when/if database needs to be updated to reflect this fact.

Riley_Huntley raised the priority of this task from High to Unbreak Now!.May 9 2016, 8:42 AM

https://commons.wikimedia.org/wiki/File:Jfdg_hfhu_pprsdrsd_gegjg.webm Exception encountered, of type "LocalFileLockError"

Upping priority, we need to be able to delete copyright violations.

Restricted Application added subscribers: Luke081515, Urbanecm. · View Herald TranscriptMay 9 2016, 8:42 AM
Aklapper lowered the priority of this task from Unbreak Now! to High.May 9 2016, 9:13 AM

https://commons.wikimedia.org/wiki/File:Jfdg_hfhu_pprsdrsd_gegjg.webm Exception encountered, of type "LocalFileLockError"
Upping priority, we need to be able to delete copyright violations.

You still should be able, if I understand correctly. (The file you linked seems to be gone.)

From the infrastructure point of view, it looks as if the file was actually successful deleted, but the database wasn't updated to reflect this. I will leave the why to the mediawiki people, and offer help when/if database needs to be updated to reflect this fact.

All those files seem to have been deleted now, also on the database.

A database query error has occurred. This may indicate a bug in the software.

Function: WikiPage::lockAndGetLatest
Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.16.31)

While deleting

@Riley_Huntley Were you shown an exception identifier like 'VxT6xQpAEFUAAHDo53wAAABE'? It allows developers to view error details in the logs, which is often very helpful. Judging by just the message you pasted, that looks like a different issue, but it's hard to tell.

Change 288535 had a related patch set uploaded (by Aaron Schulz):
Increase LocalFile lock() timeout and improve error message

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

czar added a subscriber: czar.EditedMay 17 2016, 1:08 AM

I got this error (that is, white page with black Courier text: Exception encountered, of type "LocalFileLockError") repeatedly with https://commons.wikimedia.org/wiki/File:Amateur_Gardening_July_2015_(20138255285)_(2).jpg
I attempted to delete it several times but when it finally went through, I had attempted to delete it manually (via the delete tab) rather than through the trashcan icon provided by the DelReqHandler gadget. Not sure if what made a difference was either time or the different technique.

Change 288535 merged by jenkins-bot:
Increase LocalFile lock() timeout and improve error message

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

  • API request failed (internal_api_error_LocalFileLockError): [VzrtXgpAID8AACKElzUAAAAH] Exception Caught: Could not acquire lock for 'Assad_Khan_3.jpg.'
  • API request failed (internal_api_error_LocalFileLockError): [VzrtXQpAMCMAACPeIVAAAABP] Exception Caught: Could not acquire lock for 'Assad_Khan.jpg.'
  • API request failed (internal_api_error_LocalFileLockError): [VzrtXQpAMCQAACe8kCIAAAAH] Exception Caught: Could not acquire lock for 'Assad_Khan_work.jpg.'
  • API request failed (internal_api_error_LocalFileLockError): [VzrtWApAEHEAAA6cY5wAAAAN] Exception Caught: Could not acquire lock for 'Assad_Khan_2.jpg.'

New error when deleting (related to this?):

API request failed (backend-fail-internal): An unknown error occurred in storage backend "local-multiwrite".

See also https://commons.wikimedia.org/wiki/Category:Deletion_bug and more complains on commons admin noticeboard by a number of admins.

Riley_Huntley added a comment.EditedMay 22 2016, 7:44 PM

Well thats a record.. 32 images in a row that I could not delete.

API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1ApAMEEAAFnDRjEAAAAT] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:16 GMT</i> <u>served by mw1230</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1ApAEHQAACKc3hQAAACV] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:16 GMT</i> <u>served by mw1136</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1ApAANEAAAYvSyYAAADA] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:16 GMT</i> <u>served by mw1206</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1ApAEHcAAHlQ4xAAAAAF] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:17 GMT</i> <u>served by mw1139</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1ApAIEEAABnEJSIAAAAV] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:16 GMT</i> <u>served by mw1195</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAMEUAAFykz9YAAADA] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:17 GMT</i> <u>served by mw1234</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAMDsAAKhiu3YAAACV] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:17 GMT</i> <u>served by mw1224</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAMEUAAFykz9kAAADU] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1234</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAANAAAGov1S0AAAAC] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:17 GMT</i> <u>served by mw1205</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAIEEAABnEJYAAAAAY] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1195</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAEGMAABLuPmYAAAAI] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:17 GMT</i> <u>served by mw1119</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAEG8AAB9hgo0AAAAG] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1131</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1QpAIEAAAGLHi-8AAABQ] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1194</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAEGQAABOAL3YAAAAL] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1120</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAEF4AAAv7McsAAAAQ] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1114</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAEHgAAF6tlSQAAAAV] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1140</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAEF4AAAv7MdIAAAAV] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1114</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAEHkAADYKumUAAAAD] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1141</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAMD0AALnTKoAAAAAD] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1226</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAMEQAAAJXDVcAAACT] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1233</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAAM8AADKQVHIAAACR] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1204</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAID8AACY0pOgAAAAA] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1193</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAMCEAAE-7T3wAAACW] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:18 GMT</i> <u>served by mw1201</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1gpAMEAAAAaUlusAAAAE] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1229</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAMEMAAEsnRzkAAABW] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1232</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAANAAAGov1gkAAAAE] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1205</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAANIAADZpB2kAAACK] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1207</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAMEYAALDLiHIAAAAH] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1235</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAMCEAAE-7T@kAAACM] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1201</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAIEEAABnEJkUAAAAS] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1195</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAEHYAAG5ovIcAAACA] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:20 GMT</i> <u>served by mw1138</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAIEAAAGLHjNoAAABR] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:20 GMT</i> <u>served by mw1194</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAMCQAAGY8n1EAAAAW] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1208</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAIEAAAGLHjOgAAABK] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:20 GMT</i> <u>served by mw1194</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAEHEAACGaE1MAAACE] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:19 GMT</i> <u>served by mw1133</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL1wpAIDsAAENBGLIAAAAR] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:20 GMT</i> <u>served by mw1189</u>
API request failed (internal_api_error_Wikibase\Client\Usage\UsageTrackerException): [V0IL2ApAEGIAAEDx1hgAAAAK] Exception Caught: Got explicit BEGIN from Wikibase\Client\Usage\Sql\EntityUsageTable::removeUsages while atomic section(s) FileDeleteForm::doDelete are open. <i>at Sun, 22 May 2016 19:43:20 GMT</i> <u>served by mw1118</u>

@Riley_Huntley That sounds like a separate bug, Wikidata-related. Looks like it's filed as T135485.

Storkk added a subscriber: Storkk.May 24 2016, 8:47 AM

Also happened four or five times on:

API request failed (internal_api_error_LocalFileLockError): [V0QTqwpAID8AAGdG7ocAAACU] Exception Caught: Could not acquire lock for 'AMARU-Patricia.jpg' (10.959584951401 sec)

before it just worked. Image preview wouldn't load on file description page, either.

Change 293268 had a related patch set uploaded (by Aaron Schulz):
Make LocalFileLockError and error page exception

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

Change 293268 merged by jenkins-bot:
Make LocalFileLockError an error page exception

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

The error message should be less terse now.

How often does this occur when another user is not currently deleting the file? The only way that could happen would be if the lock failed to release (maybe due to some transient redis error).

Change 296676 had a related patch set uploaded (by Aaron Schulz):
Increase redisLockManager read timeout from 1 to 2 seconds

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

Change 296678 had a related patch set uploaded (by Aaron Schulz):
Use a log group for LocalFile lock errors

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

Change 296815 had a related patch set uploaded (by Aaron Schulz):
Use a log group for LocalFile lock errors

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

Change 296678 merged by jenkins-bot:
Use a log group for LocalFile lock errors

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

Change 296815 merged by jenkins-bot:
Use a log group for LocalFile lock errors

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

This is still happening. I don't believe it's due to multiple people trying to delete the files, since the files remain after failure. Possibly relevant: the files where deletion fails universally take a _long_ time to generate the thumbnails, or simply don't generate thumbnails on the File: pages.

Trying again and again sometimes works, sometimes doesn't.

Recent examples:
[[:File:BREAKFAST (held by) NORDDEUTSCHER LLOYD BREMEN (at) EN ROUTE ABOARD DAMPFER BARBAROSSA (SS;) (NYPL Hades-276248-4000013535).jpg]]
Could not acquire lock for "mwstore://local-multiwrite/local-public/8/85/BREAKFAST_(held_by)_NORDDEUTSCHER_LLOYD_BREMEN_(at)_EN_ROUTE_ABOARD_DAMPFER_BARBAROSSA_(SS;)_(NYPL_Hades-276248-4000013535).jpg".

[[:File:FRUHSTUCK_(held_by)_NORDDEUTSCHER_LLOYD_BREMEN_(at)_DAMPFER;_H.H._MEIER_(SS;)_(NYPL_Hades-276205-4000013489).tiff]]
Could not acquire lock for "mwstore://local-multiwrite/local-public/d/d8/FRUHSTUCK_(held_by)_NORDDEUTSCHER_LLOYD_BREMEN_(at)_DAMPFER;_H.H._MEIER_(SS;)_(NYPL_Hades-276205-4000013489).tiff".

Example of it working after two failed attempts:
[[:File:LUNCH_(held_by)_NORDDEUTSCHER_LLOYD_BREMEN_(at)_"SCHNELLDAMPFER_"HOHENZOLLERN"_(SS;)_(NYPL_Hades-276088-4000013324).tiff]]

aaron added a comment.Jul 4 2016, 5:48 PM

Logging indicates that the following happens:
a) many similarly named files are deleted at once, causing deadlocks in GlobalUsage::copyLocalImagelinks
b) this causes DB rollback and the unlockFiles() call in onTransactionIdle() never happens
c) RedisLockManager::destruct() *should* clear the locks at request end, but does not seem to trigger (it might be too late and the redis connection pool may be destroyed)
d) A bunch of locks are stuck for the 5 minute timeout for those files

Change 297284 had a related patch set uploaded (by Aaron Schulz):
Fixes to LocalFile::lock()

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

Change 296676 merged by jenkins-bot:
Increase redisLockManager read timeout from 1 to 2 seconds

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

Change 297284 merged by jenkins-bot:
Fixes to LocalFile::lock()

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

Storkk added a comment.Jul 6 2016, 9:06 AM

I don't think it's caused by similarity of names... The following just failed twice:

[[:File:B5c2309350800d06dc1efe7414da0fbc.jpg.jpg]]:
Could not acquire lock for "mwstore://local-multiwrite/local-public/f/f2/B5c2309350800d06dc1efe7414da0fbc.jpg.jpg".

[[:File:599full-genevieve-padalecki_.jpg]]:
Could not acquire lock for "mwstore://local-multiwrite/local-public/8/82/599full-genevieve-padalecki_.jpg".

These were the only two failures in a batch of ~70 deletions, and they failed again after a minute or so, before working on the third try just now as I'm typing.

aaron closed this task as Resolved.Jul 21 2016, 2:53 AM

According to kibana, these seem to be relatively rare now.

Josve05a added a subscriber: Josve05a.EditedJul 23 2016, 1:45 PM

I can't couldn't delete https://commons.wikimedia.org/wiki/File:%D8%B3%DB%8C%D9%86%D8%A7.PNG

Could not acquire lock for "mwstore://local-multiwrite/local-public/4/40/سینا.PNG".

It was a dupe of another file (https://commons.wikimedia.org/w/index.php?title=File:Sina0.PNG&action=edit&redlink=1) which I successfully deleted a second before trying this one. Does not seem to be a fixed issue, so marking it as resolved because it is "rare" is misleading...

(Successfully deleted minutes after)

Poyekhali reopened this task as Open.Jul 24 2016, 5:47 AM

When does "because it is rare" became a reason to close tasks as resolved...

aaron added a comment.EditedJul 24 2016, 5:00 PM

For random "can't lock", "lock wait timeout", and "deadlock" errors, it is normal to close bugs if they are rare, as long as nothing ends up corrupted.

Is there any other reason for reopening this? Is there excess or phantom contention?

matmarex removed a subscriber: matmarex.Jul 24 2016, 6:07 PM
aaron closed this task as Resolved.Jul 26 2016, 12:23 AM
Steinsplitter reopened this task as Open.EditedAug 7 2016, 7:08 AM

Unfortunately, they seems back. Cite "I get at least 20 per week closing the daily DRs.".

Can be mass delete a cause?

(@aaron hope it is okay if i am going to re-open this, especially to gave a track - otherwise users will open new task and stuff is getting spitted :-) - otherwise feel free to re-close again.)

Steinsplitter changed the task status from Open to Stalled.Aug 7 2016, 7:12 AM

T141704 is something else?

aaron removed aaron as the assignee of this task.Aug 7 2016, 7:14 AM
czar awarded a token.Aug 8 2016, 6:27 PM
czar removed a subscriber: czar.

@aaron can you check if this is still an issue, or if the related bug's solution also solved this problem? We're wondering whether the Multimedia team needs to pay attention to this or if it got fixed already.

Ramsey-WMF moved this task from Untriaged to Tracking on the Multimedia board.Oct 9 2017, 4:43 PM
Reedy added a subscriber: Reedy.Dec 8 2017, 10:23 PM
2017-12-08 22:16:19 [WisPIwpAADoAAHf0y50AAADA] mw1263 commonswiki 1.31.0-wmf.11 exception ERROR: [WisPIwpAADoAAHf0y50AAADA] /w/index.php?title=File:Test.svg&action=delete   Wikimedia\Rdbms\DBQueryError from line 1179 of /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/database/Database.php: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading?
Query: SELECT  page_latest  FROM `page`    WHERE page_id = '50159152' AND page_namespace = '6' AND page_title = 'Test.svg'  LIMIT 1   FOR UPDATE
Function: WikiPage::lockAndGetLatest
Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.48.23)
 {"exception_id":"WisPIwpAADoAAHf0y50AAADA","exception_url":"/w/index.php?title=File:Test.svg&action=delete","caught_by":"mwe_handler"}
[Exception Wikimedia\Rdbms\DBQueryError] (/srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/database/Database.php:1179) A database query error has occurred. Did you forget to run your application's database schema updater after upgrading?
Query: SELECT  page_latest  FROM `page`    WHERE page_id = '50159152' AND page_namespace = '6' AND page_title = 'Test.svg'  LIMIT 1   FOR UPDATE
Function: WikiPage::lockAndGetLatest
Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.48.23)

  #0 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/database/Database.php(991): Wikimedia\Rdbms\Database->reportQueryError(string, integer, string, string, boolean)
  #1 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/database/Database.php(1374): Wikimedia\Rdbms\Database->query(string, string)
  #2 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/database/Database.php(1200): Wikimedia\Rdbms\Database->select(string, string, array, string, array, array)
  #3 /srv/mediawiki/php-1.31.0-wmf.11/includes/page/WikiPage.php(2994): Wikimedia\Rdbms\Database->selectField(string, string, array, string, array)
  #4 /srv/mediawiki/php-1.31.0-wmf.11/includes/page/WikiPage.php(2815): WikiPage->lockAndGetLatest()
  #5 /srv/mediawiki/php-1.31.0-wmf.11/includes/FileDeleteForm.php(197): WikiPage->doDeleteArticleReal(string, boolean, integer, boolean, string, User, array)
  #6 /srv/mediawiki/php-1.31.0-wmf.11/includes/FileDeleteForm.php(119): FileDeleteForm::doDelete(Title, LocalFile, string, string, boolean, User)
  #7 /srv/mediawiki/php-1.31.0-wmf.11/includes/page/ImagePage.php(992): FileDeleteForm->execute()
  #8 /srv/mediawiki/php-1.31.0-wmf.11/includes/actions/DeleteAction.php(46): ImagePage->delete()
  #9 /srv/mediawiki/php-1.31.0-wmf.11/includes/MediaWiki.php(499): DeleteAction->show()
--
2017-12-08 22:16:19 [WisPIwpAADoAAHf0y50AAADA] mw1263 commonswiki 1.31.0-wmf.11 exception ERROR: [WisPIwpAADoAAHf0y50AAADA] /w/index.php?title=File:Test.svg&action=delete   Wikimedia\Rdbms\DBTransactionError from line 1213 of /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/loadbalancer/LoadBalancer.php: Explicit transaction still active. A caller may have caught an error. {"exception_id":"WisPIwpAADoAAHf0y50AAADA","exception_url":"/w/index.php?title=File:Test.svg&action=delete","caught_by":"mwe_handler"}
[Exception Wikimedia\Rdbms\DBTransactionError] (/srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/loadbalancer/LoadBalancer.php:1213) Explicit transaction still active. A caller may have caught an error.
  #0 [internal function]: Closure$Wikimedia\Rdbms\LoadBalancer::approveMasterChanges(Wikimedia\Rdbms\DatabaseMysqli)
  #1 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1556): call_user_func_array(Closure$Wikimedia\Rdbms\LoadBalancer::approveMasterChanges;352, array)
  #2 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1233): Wikimedia\Rdbms\LoadBalancer->forEachOpenMasterConnection(Closure$Wikimedia\Rdbms\LoadBalancer::approveMasterChanges;352)
  #3 [internal function]: Wikimedia\Rdbms\LoadBalancer->approveMasterChanges(array)
  #4 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/lbfactory/LBFactory.php(184): call_user_func_array(array, array)
  #5 [internal function]: Closure$Wikimedia\Rdbms\LBFactory::forEachLBCallMethod(Wikimedia\Rdbms\LoadBalancer, string, array)
  #6 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(425): call_user_func_array(Closure$Wikimedia\Rdbms\LBFactory::forEachLBCallMethod;244, array)
  #7 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/lbfactory/LBFactory.php(187): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure$Wikimedia\Rdbms\LBFactory::forEachLBCallMethod;244, array)
  #8 /srv/mediawiki/php-1.31.0-wmf.11/includes/libs/rdbms/lbfactory/LBFactory.php(224): Wikimedia\Rdbms\LBFactory->forEachLBCallMethod(string, array)
  #9 /srv/mediawiki/php-1.31.0-wmf.11/includes/MediaWiki.php(881): Wikimedia\Rdbms\LBFactory->commitMasterChanges(string)
  #10 /srv/mediawiki/php-1.31.0-wmf.11/includes/MediaWiki.php(719): MediaWiki->restInPeace(string, boolean)
  #11 [internal function]: Closure$MediaWiki::doPostOutputShutdown()
  #12 {main}

I guess Test.svg is a really problem (limit) indicator, as this has the ongoing growing longest file history ever (+ already deletions).