PHP Deprecated: Caller ignored an error raised from SpecialRecentChanges::doMainQuery (max_statement_time exceeded)
Open, Needs TriagePublicPRODUCTION ERROR
Actions

Assigned To

Authored By

	thcipriani
	Mar 17 2022, 3:28 PM

Description

Error

mwversion: 1.38.0-wmf.26
reqId: 4ea30499-4ecc-4b6c-9a6a-481ea21f8ca9
Find reqId in Logstash

normalized_message

[{reqId}] {exception_url}   PHP Deprecated: Caller from TranslatablePage::getTag ignored an error originally raised from SpecialRecentChanges::doMainQuery: [1969] Query execution was interrupted (max_statement_time exceeded) (db1166)

exception.trace

from /srv/mediawiki/php-1.38.0-wmf.26/includes/debug/MWDebug.php(377)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.38.0-wmf.26/includes/debug/MWDebug.php(377): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.38.0-wmf.26/includes/db/MWLBFactory.php(436): MWDebug::sendRawDeprecated(string, boolean, string)
#3 [internal function]: MWLBFactory::logDeprecation(string)
#4 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/TransactionManager.php(215): call_user_func(array, string)
#5 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/Database.php(1548): Wikimedia\Rdbms\TransactionManager->assertTransactionStatus(Wikimedia\Rdbms\DatabaseMysqli, array, string)
#6 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/Database.php(1221): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
#7 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/Database.php(1953): Wikimedia\Rdbms\Database->query(string, string, integer)
#8 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/Database.php(1792): Wikimedia\Rdbms\Database->select(string, string, array, string, array, array)
#9 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/DBConnRef.php(69): Wikimedia\Rdbms\Database->selectField(string, string, array, string, array)
#10 /srv/mediawiki/php-1.38.0-wmf.26/includes/libs/rdbms/database/DBConnRef.php(306): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#11 /srv/mediawiki/php-1.38.0-wmf.26/extensions/Translate/tag/TranslatablePage.php(410): Wikimedia\Rdbms\DBConnRef->selectField(string, string, array, string, array)
#12 /srv/mediawiki/php-1.38.0-wmf.26/extensions/Translate/tag/TranslatablePage.php(351): TranslatablePage->getTag(string)
#13 /srv/mediawiki/php-1.38.0-wmf.26/extensions/Translate/tag/TranslatablePage.php(651): TranslatablePage->getMarkedTag()
#14 /srv/mediawiki/php-1.38.0-wmf.26/extensions/Translate/tag/PageTranslationHooks.php(169): TranslatablePage::isTranslationPage(Title)
#15 /srv/mediawiki/php-1.38.0-wmf.26/includes/HookContainer/HookContainer.php(338): PageTranslationHooks::fetchTranslatableTemplateAndTitle(Title, Title, boolean, NULL)
#16 /srv/mediawiki/php-1.38.0-wmf.26/includes/HookContainer/HookContainer.php(137): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#17 /srv/mediawiki/php-1.38.0-wmf.26/includes/HookContainer/HookRunner.php(974): MediaWiki\HookContainer\HookContainer->run(string, array)
#18 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(3643): MediaWiki\HookContainer\HookRunner->onBeforeParserFetchTemplateRevisionRecord(Title, Title, boolean, NULL)
#19 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(3579): Parser->statelessFetchTemplate(Title, Parser)
#20 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(3473): Parser->fetchTemplateAndTitle(Title)
#21 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(3212): Parser->getTemplateDom(Title)
#22 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/PPFrame_Hash.php(276): Parser->braceSubstitution(array, PPFrame_Hash)
#23 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(2932): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#24 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(1579): Parser->replaceVariables(string)
#25 /srv/mediawiki/php-1.38.0-wmf.26/includes/parser/Parser.php(697): Parser->internalParse(string)
#26 /srv/mediawiki/php-1.38.0-wmf.26/includes/cache/MessageCache.php(1323): Parser->parse(string, Title, ParserOptions, boolean)
#27 /srv/mediawiki/php-1.38.0-wmf.26/includes/specials/SpecialRecentChanges.php(735): MessageCache->parse(string, Title, boolean, boolean, LanguageEn)
#28 /srv/mediawiki/php-1.38.0-wmf.26/includes/specials/SpecialRecentChanges.php(617): SpecialRecentChanges->setTopText(FormOptions)
#29 /srv/mediawiki/php-1.38.0-wmf.26/includes/specialpage/ChangesListSpecialPage.php(1537): SpecialRecentChanges->doHeader(FormOptions, integer)
#30 /srv/mediawiki/php-1.38.0-wmf.26/includes/specialpage/ChangesListSpecialPage.php(666): ChangesListSpecialPage->webOutputHeader(integer, FormOptions)
#31 /srv/mediawiki/php-1.38.0-wmf.26/includes/specials/SpecialRecentChanges.php(205): ChangesListSpecialPage->execute(NULL)
#32 /srv/mediawiki/php-1.38.0-wmf.26/includes/specialpage/SpecialPage.php(671): SpecialRecentChanges->execute(NULL)
#33 /srv/mediawiki/php-1.38.0-wmf.26/includes/specialpage/SpecialPageFactory.php(1378): SpecialPage->run(NULL)
#34 /srv/mediawiki/php-1.38.0-wmf.26/includes/MediaWiki.php(315): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, RequestContext)
#35 /srv/mediawiki/php-1.38.0-wmf.26/includes/MediaWiki.php(910): MediaWiki->performRequest()
#36 /srv/mediawiki/php-1.38.0-wmf.26/includes/MediaWiki.php(564): MediaWiki->main()
#37 /srv/mediawiki/php-1.38.0-wmf.26/index.php(53): MediaWiki->run()
#38 /srv/mediawiki/php-1.38.0-wmf.26/index.php(46): wfIndexMain()
#39 /srv/mediawiki/w/index.php(3): require(string)
#40 {main}

new with 1.38.0-wmf.26
Happening at a rate of about once an hour

Details

MediaWiki Version: 1.38.0-wmf.26
Request URL: https://www.mediawiki.org/w/index.php?userExpLevel=*&hidebots=*&translations=*&hidecategorization=*&hideWikibase=*&limit=*&days=*&enhanced=*&userExpLevel__unregistered_color=*&userExpLevel__newcomer_color=*&title=*&urlversion=*&action=render

Related Objects

Mentioned In: T311360: RecentChanges timing out
T307132: PHP Deprecated: Caller from Wikimedia\Rdbms\Database::ping ignored an error originally raised from WikiPage::updateRevisionOn: [1205] Lock wait timeout exceeded; try restarting transaction ([db])
T304960: Caller ignored an error originally raised from IndexPager::buildQueryInfo or ApiQueryUserContribs::execute
Mentioned Here: T175776: Display custom message to user for query timeouts
T297708: Set max execution time for several expensive mediawiki actions

Event Timeline

thcipriani created this task.Mar 17 2022, 3:28 PM

Restricted Application added a project: Growth-Team. · View Herald TranscriptMar 17 2022, 3:28 PM

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

Yesterday I got an error for RecentChanges, and today another one:

MediaWiki internal error.
Original exception: [8bd95048-cc63-494f-992e-045b5e36d82f] 2022-03-21 09:19:50: Fatal exception of type "Wikimedia\Rdbms\DBQueryError"
Exception caught inside exception handler.
Set $wgShowExceptionDetails = true; at the bottom of LocalSettings.php to show detailed debugging information.

I don't know if the error is the same. This happened only one time, and after refreshing the page, it worked correctly during all the day. I guess it's somewhere near the execution time limit.

Today the error was consistently reproduced.

My RC URL is this one:

https://www.mediawiki.org/wiki/Special:RecentChanges?userExpLevel=unregistered%3Bnewcomer&hidebots=1&translations=filter&hidecategorization=1&hideWikibase=1&limit=250&days=7&enhanced=1&tagfilter__mw-reverted_color=c1&urlversion=2

I had to reduce the number of days to 2 instead of 7 for the page to load without errors. Then the page loaded fine even when using 7 days, and it worked for a while. Then, the error happens again.

Since several months ago, the RecentChanges page takes several seconds to render (in the order of 10 seconds or more), and looks like the time it takes is growing...

TranslatablePage::getTag comes from MediaWiki-extensions-Translate

In T304085#7791938, @kostajh wrote:

TranslatablePage::getTag comes from MediaWiki-extensions-Translate

Yes, but what should the code in TranslatablePage::getTag do? The code in that function runs a SELECT query. Should we fetch the IDatabase::lastError() and if there has been an error abort? From the error message it looks like the actual timeout happened in SpecialRecentChanges::doMainQuery.

Krinkle renamed this task from PHP Deprecated: Caller from TranslatablePage::getTag ignored an error originally raised from SpecialRecentChanges::doMainQuery: [1969] Query execution was interrupted (max_statement_time exceeded) (db1166) to PHP Deprecated: Caller ignored an error raised from SpecialRecentChanges::doMainQuery (max_statement_time exceeded).Mar 22 2022, 1:59 PM

In T304085#7792770, @abi_ wrote:

In T304085#7791938, @kostajh wrote:

TranslatablePage::getTag comes from MediaWiki-extensions-Translate

Yes, but what should the code in TranslatablePage::getTag do? The code in that function runs a SELECT query. Should we fetch the IDatabase::lastError() and if there has been an error abort? From the error message it looks like the actual timeout happened in SpecialRecentChanges::doMainQuery.

The timeout indeed comes from SpecialRecentChanges::doMainQuery where its select() query will have resulted in a DBQueryTimeoutError.

The Translate extension happens to be the first thing to perform a database query, after the (incorrect) handling of this DBQueryTimeoutError.

We report these warnings in this way because usually the code doing a database query after catching a database exception is also the one responsible, given that database exceptions are usually fatal or near-fatal with very little code running after that, especially database queries.

In this case, the exception thrown in SpecialRecentChanges::doMainQuery is caught by its caller in the parent class, ChangesListSpecialPage::execute() which is try-catching this query and then logging the exception but failing to properly take care of the database handle (e.g. by rolling back the transaction).

This is caused by the changes from T297708. Un-tagging LangEng and PlatformEng, re-tagging Growth and CC-ing @Ladsgroup.

Krinkle moved this task from Untriaged to Mar 2022 on the Wikimedia-production-error board.Mar 22 2022, 2:06 PM

Zabe subscribed.Mar 23 2022, 2:08 PM

Still seen. Sometimes with code paths other than Translate, e.g.:

Cannot execute query from MediaWiki\Extension\OAuth\Backend\Hooks::getUsedConsumerTags while transaction status is ERROR

from MediaWiki\Extension\OAuth\Backend\Hooks::getUsedConsumerTags(boolean, array)

After:

Error 1969: Query execution was interrupted (max_statement_time exceeded) (db1165)
Function: IndexPager::buildQueryInfo (LogPager)

And:

Cannot execute query from User::loadFromDatabase while transaction status is ERROR

from User->loadFromDatabase(integer)

after

`
 Query execution was interrupted (max_statement_time exceeded) (db1099:3311)
Function: SpecialRecentChanges::doMainQuery

Restricted Application added a project: User-Ladsgroup. · View Herald TranscriptMar 24 2022, 4:31 PM

I will take a look at this but I've been sick this week so I need some time to go through my list and everything.

Catching DB Errors is a bad idea and highly discouraged: https://www.mediawiki.org/wiki/Database_transactions#Use_of_transaction_rollback

Callers might catch DBError exceptions without either re-throwing them or throwing their own version of the error. Doing so is extremely bad practice and can cause all sorts of problems from partial commits to simply spewing up DBTransactionError errors. Only catch DB errors in order to do some cleanup before re-throwing an error or if the database in question is used exclusively by the code catching errors.

I think ChangesListSpecialPage::execute() needs to rethrow the exception. How does that sound to you @Krinkle ?

Nikerabbit subscribed.Mar 27 2022, 4:12 PM

Krinkle mentioned this in T304960: Caller ignored an error originally raised from IndexPager::buildQueryInfo or ApiQueryUserContribs::execute.Apr 7 2022, 2:58 PM

@Ladsgroup Yes, I agree. Note that RCFilters relies on this currently, T175776 and https://gerrit.wikimedia.org/r/c/mediawiki/core/+/378687/, so it would need some frontend changes as well to make sure the partial HTML response the live updating interface gets still renders the same custom message for this.

Alternatively, as long as it calls rollback, it should be fine as well afaik. Detecting a timeout from an otherwise standard HTTP 50x response may get ugly.

Ladsgroup mentioned this in T307132: PHP Deprecated: Caller from Wikimedia\Rdbms\Database::ping ignored an error originally raised from WikiPage::updateRevisionOn: [1205] Lock wait timeout exceeded; try restarting transaction ([db]).Apr 28 2022, 6:37 PM

Marostegui removed Ladsgroup as the assignee of this task.May 23 2022, 1:32 PM

Marostegui assigned this task to Ladsgroup.

Marostegui moved this task from Triage to Ready on the DBA board.

Umherirrender mentioned this in T311360: RecentChanges timing out.Jun 26 2022, 9:57 PM