Page MenuHomePhabricator

Job queue cannot claim job on sqlite due to db being locked
Closed, InvalidPublic

Description

I haven't really debuged this. However on a vanilla MW install, using sqlite db backend, and defaults pretty much everything else (In particular $wgRunJobsAsync = false), I get the following error bascially any time I edit (in particular seems to happen when I include a new template)

MediaWiki internal error.

Original exception: [565b6eb58cbf0f40268c59c7] /w/index.php/Main_Page JobQueueError from line 813 of /vagrant/mediawiki/includes/jobqueue/JobQueueDB.php: DBQueryError: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading?
Query: UPDATE job SET job_token = 'ad165491407b83281cbed89298c47a29',job_token_timestamp = '20170321082350',job_attempts = job_attempts+1 WHERE job_cmd = 'recentChangesUpdate' AND job_id = '29' AND job_token = ''
Function: JobQueueDB::claimRandom
Error: 5 database is locked

Backtrace:
#0 /vagrant/mediawiki/includes/jobqueue/JobQueueDB.php(304): JobQueueDB->throwDBException(DBQueryError)
#1 /vagrant/mediawiki/includes/jobqueue/JobQueue.php(373): JobQueueDB->doPop()
#2 /vagrant/mediawiki/includes/jobqueue/JobQueueGroup.php(240): JobQueue->pop()
#3 /vagrant/mediawiki/includes/jobqueue/JobRunner.php(161): JobQueueGroup->pop(integer, integer, array)
#4 /vagrant/mediawiki/includes/MediaWiki.php(950): JobRunner->run(array)
#5 /vagrant/mediawiki/includes/MediaWiki.php(909): MediaWiki->triggerJobs()
#6 /vagrant/mediawiki/includes/MediaWiki.php(729): MediaWiki->restInPeace(string)
#7 /vagrant/mediawiki/includes/MediaWiki.php(748): MediaWiki->{closure}()
#8 /vagrant/mediawiki/includes/MediaWiki.php(552): MediaWiki->doPostOutputShutdown(string)
#9 /vagrant/mediawiki/index.php(43): MediaWiki->run()
#10 /var/www/w/index.php(5): require(string)
#11 {main}

Exception caught inside exception handler: [565b6eb58cbf0f40268c59c7] /w/index.php/Main_Page DBQueryError from line 1061 of /vagrant/mediawiki/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: BEGIN
Function: Database::query (LinkBatch::doQuery (for Skin::preloadExistence))
Error: 1 cannot start a transaction within a transaction

Backtrace:
#0 /vagrant/mediawiki/includes/libs/rdbms/database/Database.php(919): Database->reportQueryError(string, integer, string, string, boolean)
#1 /vagrant/mediawiki/includes/libs/rdbms/database/DatabaseSqlite.php(743): Database->query(string, string)
#2 /vagrant/mediawiki/includes/libs/rdbms/database/Database.php(2707): DatabaseSqlite->doBegin(string)
#3 /vagrant/mediawiki/includes/libs/rdbms/database/Database.php(858): Database->begin(string, string)
#4 /vagrant/mediawiki/includes/libs/rdbms/database/Database.php(1255): Database->query(string, string)
#5 /vagrant/mediawiki/includes/cache/LinkBatch.php(210): Database->select(string, array, string, string)
#6 /vagrant/mediawiki/includes/cache/LinkBatch.php(138): LinkBatch->doQuery()
#7 /vagrant/mediawiki/includes/cache/LinkBatch.php(127): LinkBatch->executeInto(LinkCache)
#8 /vagrant/mediawiki/includes/skins/Skin.php(249): LinkBatch->execute()
#9 /vagrant/mediawiki/includes/skins/Skin.php(145): Skin->preloadExistence()
#10 /vagrant/mediawiki/skins/Vector/SkinVector.php(47): Skin->initPage(OutputPage)
#11 /vagrant/mediawiki/includes/skins/SkinTemplate.php(248): SkinVector->initPage(OutputPage)
#12 /vagrant/mediawiki/includes/OutputPage.php(2400): SkinTemplate->outputPage()
#13 /vagrant/mediawiki/includes/exception/MWException.php(174): OutputPage->output()
#14 /vagrant/mediawiki/includes/exception/MWException.php(220): MWException->reportHTML()
#15 /vagrant/mediawiki/includes/exception/MWExceptionHandler.php(72): MWException->report()
#16 /vagrant/mediawiki/includes/exception/MWExceptionHandler.php(140): MWExceptionHandler::report(JobQueueError)
#17 /vagrant/mediawiki/includes/MediaWiki.php(731): MWExceptionHandler::handleException(JobQueueError)
#18 /vagrant/mediawiki/includes/MediaWiki.php(748): MediaWiki->{closure}()
#19 /vagrant/mediawiki/includes/MediaWiki.php(552): MediaWiki->doPostOutputShutdown(string)
#20 /vagrant/mediawiki/index.php(43): MediaWiki->run()
#21 /var/www/w/index.php(5): require(string)
#22 {main}

MediaWiki: 1.29.0-alpha (69fab9a)
Git branch: master
PHP: 5.5.9-1ubuntu4.20
Time: 0.27421
Memory: 6.71 MB (Peak: 6.85 MB)

(Note, despite the /vagrant in the path, this is not using vagrant's LocalSettings.php)

Event Timeline

Bawolff created this task.Mar 21 2017, 8:27 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 21 2017, 8:27 AM
Krinkle added a subscriber: Krinkle.Jul 4 2017, 1:00 AM

@Bawolff A fair number of changes have been made to the JobQueue handling in the request shutdown process. Can you verify this once more on latest master? Also, it would help if you could find out what code path is holding the lock when JobRunner in post-shutdown is trying to pop the job.

There shouldn't be anything else doing transactions at that point, given it's in top scope and post-shutdown. Looks like something in core or an extension is leaving a transaction uncommitted and we fail to detect it (I thought we had logging for that). Do you find anything else useful in the logs alongside this exception?

Bawolff closed this task as Invalid.Jul 4 2017, 5:57 PM

@Bawolff A fair number of changes have been made to the JobQueue handling in the request shutdown process. Can you verify this once more on latest master? Also, it would help if you could find out what code path is holding the lock when JobRunner in post-shutdown is trying to pop the job.
There shouldn't be anything else doing transactions at that point, given it's in top scope and post-shutdown. Looks like something in core or an extension is leaving a transaction uncommitted and we fail to detect it (I thought we had logging for that). Do you find anything else useful in the logs alongside this exception?

I can no longer reproduce