Page MenuHomePhabricator
Create Task
Maniphest T279409

[8h] Logspam about an "ignored error" in Wikibase\Repo\Content\DataUpdateAdapter::doUpdate
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error
normalized_message
[{reqId}] {exception_url}   ErrorException: PHP Deprecated: Caller from Wikibase\Repo\Content\DataUpdateAdapter::doUpdate ignored an error originally raised from Wikibase\Lib\Store\Sql\Terms\DatabaseTermStoreWriterBase::acquireAndInsertTerms: [1205] Lock
exception.trace
from /srv/mediawiki/php-1.36.0-wmf.37/includes/debug/MWDebug.php(376)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.36.0-wmf.37/includes/debug/MWDebug.php(376): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.36.0-wmf.37/includes/db/MWLBFactory.php(349): MWDebug::sendRawDeprecated(string, boolean, string)
#3 [internal function]: MWLBFactory::logDeprecation(string)
#4 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(1531): call_user_func(array, string)
#5 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(1237): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
#6 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(4666): Wikimedia\Rdbms\Database->query(string, string, integer)
#7 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(4634): Wikimedia\Rdbms\Database->doCommit(string)
#8 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1812): Wikimedia\Rdbms\Database->commit(string, string)
#9 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(2255): Wikimedia\Rdbms\LoadBalancer->Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#10 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1817): Wikimedia\Rdbms\LoadBalancer->forEachOpenMasterConnection(Closure)
#11 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(247): Wikimedia\Rdbms\LoadBalancer->commitMasterChanges(string, integer)
#12 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(236): Wikimedia\Rdbms\LBFactory::Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\LoadBalancer, string, array)
#13 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(249): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure, array)
#14 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(312): Wikimedia\Rdbms\LBFactory->forEachLBCallMethod(string, array)
#15 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(515): Wikimedia\Rdbms\LBFactory->commitMasterChanges(string)
#16 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/RefreshSecondaryDataUpdate.php(101): DeferredUpdates::attemptUpdate(Wikibase\Repo\Content\DataUpdateAdapter, Wikimedia\Rdbms\LBFactoryMulti)
#17 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(513): RefreshSecondaryDataUpdate->doUpdate()
#18 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(390): DeferredUpdates::attemptUpdate(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactoryMulti)
#19 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(221): DeferredUpdates::run(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactoryMulti, Monolog\Logger, BufferingStatsdDataFactory, string)
#20 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdatesScope.php(264): DeferredUpdates::{closure}(RefreshSecondaryDataUpdate, integer)
#21 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#22 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(242): DeferredUpdatesScope->processUpdates(integer, Closure)
#23 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(1093): DeferredUpdates::doUpdates(string)
#24 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(821): MediaWiki->restInPeace()
#25 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(833): MediaWiki->{closure}()
#26 /srv/mediawiki/php-1.36.0-wmf.37/api.php(125): MediaWiki->doPostOutputShutdown()
#27 /srv/mediawiki/php-1.36.0-wmf.37/api.php(45): wfApiMain()
#28 /srv/mediawiki/w/api.php(3): require(string)
#29 {main}
Impact

We seem to leave something in the DB layer in an odd / unexpected state
The logspam comes form https://gerrit.wikimedia.org/g/mediawiki/core/+/494f15438182a706094784c0c7a5ffe9bf478263/includes/libs/rdbms/database/Database.php#1530
Seemingly just calling $this->exceptionHandler->handleException is not the right / only thing we need to do, but the DB layer needs to be put in some better state when we would encounter this initial lock?

	public function doUpdate() {
		try {
			( $this->doUpdateFunction )( ...$this->arguments );
		} catch ( Exception $ex ) {
			$this->exceptionHandler->handleException( $ex, 'data-update-failed',
				'A data update callback triggered an exception' );
		}
	}
Notes

Details

Request ID
176a8ee3-cfd9-4432-b1e6-bed1a5bc3add
Request URL
https://www.wikidata.org/w/api.php
Stack Trace
from /srv/mediawiki/php-1.36.0-wmf.37/includes/debug/MWDebug.php(376)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.36.0-wmf.37/includes/debug/MWDebug.php(376): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.36.0-wmf.37/includes/db/MWLBFactory.php(349): MWDebug::sendRawDeprecated(string, boolean, string)
#3 [internal function]: MWLBFactory::logDeprecation(string)
#4 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(1531): call_user_func(array, string)
#5 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(1237): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
#6 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(4666): Wikimedia\Rdbms\Database->query(string, string, integer)
#7 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/database/Database.php(4634): Wikimedia\Rdbms\Database->doCommit(string)
#8 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1812): Wikimedia\Rdbms\Database->commit(string, string)
#9 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(2255): Wikimedia\Rdbms\LoadBalancer->Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#10 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1817): Wikimedia\Rdbms\LoadBalancer->forEachOpenMasterConnection(Closure)
#11 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(247): Wikimedia\Rdbms\LoadBalancer->commitMasterChanges(string, integer)
#12 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(236): Wikimedia\Rdbms\LBFactory::Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\LoadBalancer, string, array)
#13 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(249): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure, array)
#14 /srv/mediawiki/php-1.36.0-wmf.37/includes/libs/rdbms/lbfactory/LBFactory.php(312): Wikimedia\Rdbms\LBFactory->forEachLBCallMethod(string, array)
#15 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(515): Wikimedia\Rdbms\LBFactory->commitMasterChanges(string)
#16 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/RefreshSecondaryDataUpdate.php(101): DeferredUpdates::attemptUpdate(Wikibase\Repo\Content\DataUpdateAdapter, Wikimedia\Rdbms\LBFactoryMulti)
#17 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(513): RefreshSecondaryDataUpdate->doUpdate()
#18 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(390): DeferredUpdates::attemptUpdate(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactoryMulti)
#19 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(221): DeferredUpdates::run(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactoryMulti, Monolog\Logger, BufferingStatsdDataFactory, string)
#20 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdatesScope.php(264): DeferredUpdates::{closure}(RefreshSecondaryDataUpdate, integer)
#21 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#22 /srv/mediawiki/php-1.36.0-wmf.37/includes/deferred/DeferredUpdates.php(242): DeferredUpdatesScope->processUpdates(integer, Closure)
#23 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(1093): DeferredUpdates::doUpdates(string)
#24 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(821): MediaWiki->restInPeace()
#25 /srv/mediawiki/php-1.36.0-wmf.37/includes/MediaWiki.php(833): MediaWiki->{closure}()
#26 /srv/mediawiki/php-1.36.0-wmf.37/api.php(125): MediaWiki->doPostOutputShutdown()
#27 /srv/mediawiki/php-1.36.0-wmf.37/api.php(45): wfApiMain()
#28 /srv/mediawiki/w/api.php(3): require(string)
#29 {main}
SubjectRepoBranchLines +/-
Don't catch TermStoreExceptionmediawiki/extensions/Wikibasemaster+10 -93
Re-throw DBErrors in DataUpdateAdaptermediawiki/extensions/WikibaseREL1_36+21 -0
Re-throw DBErrors in DataUpdateAdaptermediawiki/extensions/Wikibasemaster+21 -0
Customize query in gerrit

Event Timeline

Michael created this task.Apr 6 2021, 7:03 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 6 2021, 7:03 AM
Addshore added a project: Wikidata-Campsite.Apr 6 2021, 11:49 AM
Addshore moved this task from Incoming to Prioritized Wikidata Tech Backlog (prioritised from top to bottom) on the Wikidata-Campsite board.
Addshore moved this task from Inbox to Triaged Low (0-50) on the [DEPRECATED] wdwb-tech board.Apr 6 2021, 11:52 AM
Addshore subscribed.Apr 6 2021, 2:46 PM

The Php Deprecated part of the message comes form https://gerrit.wikimedia.org/g/mediawiki/core/+/494f15438182a706094784c0c7a5ffe9bf478263/includes/exception/MWExceptionHandler.php#251
The bulk of the rest of the messge ignored an error originally raised from comes from https://gerrit.wikimedia.org/g/mediawiki/core/+/494f15438182a706094784c0c7a5ffe9bf478263/includes/libs/rdbms/database/Database.php#1530
Seemingly a lock is encountered, and the db layer expects something extra to happen to "tidy up" the connection, instead of just handling the exception

Addshore renamed this task from False positive logspam about an (not actually) ignored error in Wikibase\Repo\Content\DataUpdateAdapter::doUpdate to Logspam about an "ignored error" in Wikibase\Repo\Content\DataUpdateAdapter::doUpdate.Apr 6 2021, 2:50 PM
Addshore updated the task description. (Show Details)
Addshore added a comment.Apr 7 2021, 10:30 AM

THis task talks about locks.
A possible way to try and reproduce the situation locally would be using breakpoints.
Find the location just after the lock that is being encountered, and put a breakpoint there.
Then fire up another request that is going to encounter that lock and reach this "error state"

Addshore edited Stack Trace. (Show Details)Apr 7 2021, 10:32 AM
noarave renamed this task from Logspam about an "ignored error" in Wikibase\Repo\Content\DataUpdateAdapter::doUpdate to [8h] Logspam about an "ignored error" in Wikibase\Repo\Content\DataUpdateAdapter::doUpdate.Apr 7 2021, 10:32 AM
darthmon_wmde moved this task from Prioritized Wikidata Tech Backlog (prioritised from top to bottom) to Wikidata-Campsite-Iteration-∞ (On Hold) on the Wikidata-Campsite board.Apr 7 2021, 10:46 AM
darthmon_wmde edited projects, added Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)); removed Wikidata-Campsite.
Maintenance_bot moved this task from incoming to in progress on the Wikidata board.Apr 7 2021, 11:15 AM
Jakob_WMDE claimed this task.Apr 13 2021, 8:49 AM
Jakob_WMDE moved this task from To Do (prioritised from top to bottom) to Doing on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.
Jakob_WMDE removed Jakob_WMDE as the assignee of this task.Apr 13 2021, 8:51 AM
Jakob_WMDE moved this task from Doing to To Do (prioritised from top to bottom) on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.
Jakob_WMDE subscribed.
Krinkle moved this task from Untriaged to Apr 2021 on the Wikimedia-production-error board.Apr 14 2021, 7:12 PM
gerritbot added a comment.Apr 15 2021, 12:25 AM

Change 679529 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):

[mediawiki/extensions/Wikibase@master] Don't catch TermStoreException

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

gerritbot added a project: Patch-For-Review.Apr 15 2021, 12:25 AM
Ladsgroup subscribed.Apr 15 2021, 12:51 AM

Oh this is another case of catching DBErrors.
See https://www.mediawiki.org/wiki/Database_transactions#Use_of_transaction_rollback (emphasis not mine)

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.

Funnily enough, we don't catch any db error in our codebase (the only one we catch is never thrown, removing that for good measure), it's happening in core meaning this warning will likely continue to pop up in different shape and form for different extensions or basically anything that does sql queries in deferred updates.

Ladsgroup added a comment.Apr 15 2021, 1:01 AM

oh my bad, we do catch db errors in DataUpdateAdapter, I thought it's a core class. Making a patch now.

gerritbot added a comment.Apr 15 2021, 1:14 AM

Change 679533 had a related patch set uploaded (by Ladsgroup; author: Ladsgroup):

[mediawiki/extensions/Wikibase@master] Re-throw DBErrors in DataUpdateAdapter

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

Ladsgroup claimed this task.Apr 15 2021, 1:21 AM
Ladsgroup moved this task from To Do (prioritised from top to bottom) to Peer Review on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.
Restricted Application added a project: User-Ladsgroup. · View Herald TranscriptApr 15 2021, 1:21 AM
Maintenance_bot moved this task from Incoming to In progress on the User-Ladsgroup board.Apr 15 2021, 2:15 AM
gerritbot added a comment.Apr 20 2021, 6:47 AM

Change 679533 merged by jenkins-bot:

[mediawiki/extensions/Wikibase@master] Re-throw DBErrors in DataUpdateAdapter

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

Ladsgroup moved this task from Peer Review to Test (Verification) on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.Apr 20 2021, 6:54 AM
ReleaseTaggerBot added a project: MW-1.37-notes (1.37.0-wmf.3; 2021-04-27).Apr 20 2021, 7:00 AM
Umherirrender added a subscriber: aaron.Apr 20 2021, 7:29 PM
Addshore moved this task from Triaged Low (0-50) to Active on the [DEPRECATED] wdwb-tech board.Apr 23 2021, 10:45 AM
Jakob_WMDE moved this task from Test (Verification) to Peer Review on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.Apr 26 2021, 9:29 AM
Jakob_WMDE moved this task from Peer Review to Test (Verification) on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.
Addshore closed this task as Resolved.May 3 2021, 9:27 AM

Going to close.
Not seen the log in prod since the 29th.
https://logstash.wikimedia.org/app/dashboards#/view/AXFV7JE83bOlOASGccsT?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-4w,to:now))&_a=(description:'All%20MediaWiki%20logs',filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'logstash-*',key:type,negate:!f,params:(query:mediawiki),type:phrase),query:(match:(type:(query:mediawiki,type:phrase)))),('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'logstash-*',key:channel,negate:!t,params:(query:api-feature-usage),type:phrase),query:(match:(channel:(query:api-feature-usage,type:phrase)))),('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'logstash-*',key:level,negate:!t,params:(query:INFO),type:phrase),query:(match:(level:(query:INFO,type:phrase))))),fullScreenMode:!f,options:(darkTheme:!f),query:(language:lucene,query:'%22acquireAndInsertTerms%22%20AND%20%22ignored%20an%20error%20originally%20raised%22'),timeRestore:!t,title:mediawiki,viewMode:view)

This could also just be because it hasn't occurred, but it looks good!

Maintenance_bot moved this task from Test (Verification) to Done on the Wikidata-Campsite (Wikidata-Campsite-Iteration-∞ (On Hold)) board.May 3 2021, 10:15 AM
Maintenance_bot moved this task from In progress to Done on the User-Ladsgroup board.
gerritbot added a comment.Sep 16 2021, 1:54 PM

Change 721529 had a related patch set uploaded (by Addshore; author: Ladsgroup):

[mediawiki/extensions/Wikibase@REL1_36] Re-throw DBErrors in DataUpdateAdapter

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

gerritbot added a comment.Sep 16 2021, 2:22 PM

Change 721529 merged by jenkins-bot:

[mediawiki/extensions/Wikibase@REL1_36] Re-throw DBErrors in DataUpdateAdapter

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

gerritbot added a comment.Mar 2 2022, 11:56 AM

Change 679529 abandoned by Silvan Heintze:

[mediawiki/extensions/Wikibase@master] Don't catch TermStoreException

Reason:

old and resolved otherwise

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

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL