Page MenuHomePhabricator

Special:MovePage throws MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush, JobQueueDB::doBatchPush)
Closed, ResolvedPublic

Description

MediaWiki 1.29.0-alpha (54381ead)
PHP	5.6.8 (apache2handler)
MySQL	5.6.24
ICU	54.1

Issue

Special:MovePage&action=submit throws a:

[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database 'localhost'.
User: loading options for user 1 from database.
OutputPage::sendCacheControl: private caching;  **
[exception] [78d49248ea787986c81ffeb1] /mw-master/index.php?title=Special:MovePage&action=submit   DBUnexpectedError from line 2851 of ...\mw-master\includes\libs\rdbms\database\Database.php: MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush, JobQueueDB::doBatchPush).
#0 ...\mw-master\includes\libs\rdbms\loadbalancer\LoadBalancer.php(1101): Database->flushSnapshot(string)
#1 [internal function]: LoadBalancer->{closure}(DatabaseMysqli)
#2 ...\mw-master\includes\libs\rdbms\loadbalancer\LoadBalancer.php(1399): call_user_func_array(Closure, array)
#3 ...\mw-master\includes\libs\rdbms\loadbalancer\LoadBalancer.php(1109): LoadBalancer->forEachOpenMasterConnection(Closure)
#4 [internal function]: LoadBalancer->beginMasterChanges(string)
#5 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(176): call_user_func_array(array, array)
#6 [internal function]: LBFactory->{closure}(LoadBalancer, string, array)
#7 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactorySimple.php(147): call_user_func_array(Closure, array)
#8 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(179): LBFactorySimple->forEachLB(Closure, array)
#9 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(200): LBFactory->forEachLBCallMethod(string, array)
#10 ...\mw-master\includes\deferred\DeferredUpdates.php(262): LBFactory->beginMasterChanges(string)
#11 ...\mw-master\includes\deferred\DeferredUpdates.php(225): DeferredUpdates::runUpdate(MWCallableUpdate, LBFactorySimple, integer)
#12 ...\mw-master\includes\deferred\DeferredUpdates.php(133): DeferredUpdates::execute(array, string, integer)
#13 ...\mw-master\includes\MediaWiki.php(891): DeferredUpdates::doUpdates(string)
#14 ...\mw-master\includes\MediaWiki.php(720): MediaWiki->restInPeace(string)
#15 ...\mw-master\includes\MediaWiki.php(739): MediaWiki->{closure}()
#16 ...\mw-master\includes\MediaWiki.php(543): MediaWiki->doPostOutputShutdown(string)
#17 ...\mw-master\index.php(43): MediaWiki->run()
#18 {main}
[Bug56269] Exception thrown with an uncommited database transaction: [78d49248ea787986c81ffeb1] /mw-master/index.php?title=Special:MovePage&action=submit   DBExpectedError from line 1112 of ...\mw-master\includes\libs\rdbms\loadbalancer\LoadBalancer.php: MWCallableUpdate::doUpdate: Flush failed on server(s) localhost: MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush, JobQueueDB::doBatchPush).
#0 [internal function]: LoadBalancer->beginMasterChanges(string)
#1 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(176): call_user_func_array(array, array)
#2 [internal function]: LBFactory->{closure}(LoadBalancer, string, array)
#3 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactorySimple.php(147): call_user_func_array(Closure, array)
#4 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(179): LBFactorySimple->forEachLB(Closure, array)
#5 ...\mw-master\includes\libs\rdbms\lbfactory\LBFactory.php(200): LBFactory->forEachLBCallMethod(string, array)
#6 ...\mw-master\includes\deferred\DeferredUpdates.php(262): LBFactory->beginMasterChanges(string)
#7 ...\mw-master\includes\deferred\DeferredUpdates.php(225): DeferredUpdates::runUpdate(MWCallableUpdate, LBFactorySimple, integer)
#8 ...\mw-master\includes\deferred\DeferredUpdates.php(133): DeferredUpdates::execute(array, string, integer)
#9 ...\mw-master\includes\MediaWiki.php(891): DeferredUpdates::doUpdates(string)
#10 ...\mw-master\includes\MediaWiki.php(720): MediaWiki->restInPeace(string)
#11 ...\mw-master\includes\MediaWiki.php(739): MediaWiki->{closure}()
#12 ...\mw-master\includes\MediaWiki.php(543): MediaWiki->doPostOutputShutdown(string)
#13 ...\mw-master\index.php(43): MediaWiki->run()
#14 {main}
[objectcache] Duplicate get(): "mw-master:prepared-edit:1e1e263a5b3e4c3f742b375650583ae1:394e974a2713b6d8f08295290194fe0bdcd4e563:47e380dbf115b201ee12fd3c3b4874f4" fetched 2 times
[objectcache] Duplicate get(): "mw-master:preprocess-xml:f45ddc89940b283c1827f6b7bcf2d7c2:0" fetched 3 times
[objectcache] Duplicate get(): "mw-master:prepared-edit:0d60c2367e4ea0d16699f21e2e0aaac4:3acc3264af7114948d2b26463f366e1315318d06:47e380dbf115b201ee12fd3c3b4874f4" fetched 2 times

SUMMARY OF T165714, T100085, and T154425

All three bugs are related to jobs (background tasks managed asynchronously) and deferred updates (also called deferrable updates, tasks postponed to the end of the request). Some deferred updates can be transformed to jobs. Jobs are usually pushed in the job queue during normal operations, but some jobs are only pushed at a latter time, these are called lazy jobs (short for lazily-pushed jobs). At the end of a MediaWiki request on the Web, deferred updates are executed, then some jobs are executed if the parameter $wgJobRunRate is not 0, and lazy jobs are pushed to the job queue.

  • T165714 (duplicates: T154439) (affects: MW 1.28, 1.29, 1.30) Some jobs throw an exception when executed on the Web due to interactions between jobs and deferred updates linked to database transactions; these jobs are never executed and remain in the job queue until deleted. Bug trigerred when $wgJobRunRate > 0 (default) and the job queue is JobQueueDB (default). Fixed by https://gerrit.wikimedia.org/r/#/c/356120/ on 1.28, 1.29, 1.30.
  • T100085 (duplicates: T154427) (affects: MW: 1.27, 1.28, 1.29, 1.30) Some lazy jobs added by jobs executed on the Web are not pushed and this triggers an error in the logs; these jobs are never added in the job queue, hence never executed. Bug trigerred when $wgJobRunRate > 0 (default). Fixed by https://gerrit.wikimedia.org/r/#/c/356120/ on 1.27, 1.28, 1.29, 1.30. The fix from T154425 improves the resolution. Possibly other root causes given it happened on Translatewiki and Wikimedia (where $wgJobRunRate is 0).

Related Objects

Mentioned In
T100085: PHP Notice: JobQueueGroup::__destruct: 1 buffered job(s) never inserted
T154439: AutoCommitUpdate::doUpdate (Title->invalidateCache) causes Exception thrown with an uncommited database transaction
T154425: Delete action throws a DBUnexpectedError with "MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush)"
T165714: BagOStuff::trackDuplicateKeys causes a "MWCallableUpdate::doUpdate: transaction round ..." during JobRunner::executeJob
T157679: Exception thrown with an uncommited database transaction: MWCallableUpdate::doUpdate: Flush failed on server(s)
Mentioned Here
T100085: PHP Notice: JobQueueGroup::__destruct: 1 buffered job(s) never inserted
T153849: Deleted pages' creation entry shows up in Special:RecentChanges as a redlink since MW 1.28
T154425: Delete action throws a DBUnexpectedError with "MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush)"
T154427: ErrorException with "PHP Notice: JobQueueGroup::__destruct: 1 buffered job ... HTMLCacheUpdateJob never inserted"
T154439: AutoCommitUpdate::doUpdate (Title->invalidateCache) causes Exception thrown with an uncommited database transaction
T157679: Exception thrown with an uncommited database transaction: MWCallableUpdate::doUpdate: Flush failed on server(s)
T165714: BagOStuff::trackDuplicateKeys causes a "MWCallableUpdate::doUpdate: transaction round ..." during JobRunner::executeJob
T166867: DBUnexpectedError from line 2877 of Database.php: MWCallableUpdate::doUpdate: Cannot flush snapshot because writes are pending (JobQueueDB::doBatchPush).

Event Timeline

Given the following message [0], are we going to address (which implicitly means solve) this with 1.29?

[0] https://lists.wikimedia.org/pipermail/wikitech-l/2017-April/088019.html

If you or anyone else plan to provide a patch in Gerrit (see Developer access and the Gerrit tutorial) for review, there is a good chance.

If you or anyone else plan to provide a patch in Gerrit (see Developer access and the Gerrit tutorial) for review, there is a good chance.

Well, this is not about a feature request, this issue appeared in connection with 1.29 and requires some root cause analysis (hence the stack trace) and is not a simple request for "If you or anyone else plan to provide a patch in Gerrit..." of some sort.

demon triaged this task as Unbreak Now! priority.May 31 2017, 6:39 PM

Change 356619 had a related patch set uploaded (by Seb35; owner: Seb35):
[mediawiki/core@master] Use AtomicSectionUpdate instead of Database->onTransactionIdle

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

Change 356619 merged by jenkins-bot:
[mediawiki/core@master] Use AutoCommitUpdate instead of Database->onTransactionIdle

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

Change 357560 had a related patch set uploaded (by Seb35; owner: Seb35):
[mediawiki/core@REL1_29] Use AutoCommitUpdate instead of Database->onTransactionIdle

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

Change 357561 had a related patch set uploaded (by Seb35; owner: Seb35):
[mediawiki/core@REL1_28] Use AutoCommitUpdate instead of Database->onTransactionIdle

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

Change 357561 merged by jenkins-bot:
[mediawiki/core@REL1_28] Use AutoCommitUpdate instead of Database->onTransactionIdle

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

Change 357560 merged by jenkins-bot:
[mediawiki/core@REL1_29] Use AutoCommitUpdate instead of Database->onTransactionIdle

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

Closed this task given it is almost a duplicate for T154425, it is solved by https://gerrit.wikimedia.org/r/#/c/356619/ (fixed in 1.28, 1.29, 1.30). An issue remains as of now, see T154425 for details.