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])
Open, Needs TriagePublicPRODUCTION ERROR
Actions

Assigned To

None

Authored By

	brennen
	Apr 28 2022, 6:31 PM

Description

Error

mwversion: 1.39.0-wmf.9
reqId: a3a6958a-cf93-4faa-8683-28e9df306763
Find reqId in Logstash

normalized_message

[{reqId}] {exception_url}   PHP Deprecated: Caller from Wikimedia\Rdbms\Database::ping ignored an error originally raised from WikiPage::updateRevisionOn: [1205] Lock wait timeout exceeded; try restarting transaction (db1100)

exception.trace

from /srv/mediawiki/php-1.39.0-wmf.9/includes/debug/MWDebug.php(380)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.39.0-wmf.9/includes/debug/MWDebug.php(380): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.39.0-wmf.9/includes/db/MWLBFactory.php(436): MWDebug::sendRawDeprecated(string, boolean, string)
#3 [internal function]: MWLBFactory::logDeprecation(string)
#4 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/TransactionManager.php(216): call_user_func(array, string)
#5 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/Database.php(1538): Wikimedia\Rdbms\TransactionManager->assertTransactionStatus(Wikimedia\Rdbms\DatabaseMysqli, array, string)
#6 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/Database.php(1205): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
#7 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/Database.php(4895): Wikimedia\Rdbms\Database->query(string, string, integer)
#8 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/TransactionManager.php(341): Wikimedia\Rdbms\Database->ping(NULL)
#9 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/database/Database.php(711): Wikimedia\Rdbms\TransactionManager->pendingWriteQueryDuration(Wikimedia\Rdbms\DatabaseMysqli, string)
#10 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1702): Wikimedia\Rdbms\Database->pendingWriteQueryDuration(string)
#11 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/loadbalancer/LoadBalancer.php(2240): Wikimedia\Rdbms\LoadBalancer->Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\DatabaseMysqli)
#12 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/loadbalancer/LoadBalancer.php(1729): Wikimedia\Rdbms\LoadBalancer->forEachOpenPrimaryConnection(Closure)
#13 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/lbfactory/LBFactory.php(250): Wikimedia\Rdbms\LoadBalancer->approvePrimaryChanges(array, string, integer)
#14 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/lbfactory/LBFactoryMulti.php(230): Wikimedia\Rdbms\LBFactory::Wikimedia\Rdbms\{closure}(Wikimedia\Rdbms\LoadBalancer, string, array)
#15 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/lbfactory/LBFactory.php(252): Wikimedia\Rdbms\LBFactoryMulti->forEachLB(Closure, array)
#16 /srv/mediawiki/php-1.39.0-wmf.9/includes/libs/rdbms/lbfactory/LBFactory.php(311): Wikimedia\Rdbms\LBFactory->forEachLBCallMethod(string, array)
#17 /srv/mediawiki/php-1.39.0-wmf.9/includes/MediaWiki.php(680): Wikimedia\Rdbms\LBFactory->commitPrimaryChanges(string, array)
#18 /srv/mediawiki/php-1.39.0-wmf.9/includes/api/ApiMain.php(900): MediaWiki::preOutputCommit(DerivativeContext)
#19 /srv/mediawiki/php-1.39.0-wmf.9/includes/api/ApiMain.php(845): ApiMain->executeActionWithErrorHandling()
#20 /srv/mediawiki/php-1.39.0-wmf.9/api.php(90): ApiMain->execute()
#21 /srv/mediawiki/php-1.39.0-wmf.9/api.php(45): wfApiMain()
#22 /srv/mediawiki/w/api.php(3): require(string)
#23 {main}

Impact

Notes

Started seeing these after 1.39.0-wmf.9 (T305215) to all wikis. Marking as blocker for next train per deprecation warning policy.

Details

Request URL: https://de.wikipedia.org/w/api.php

Related Objects

Mentioned Here: T304085: PHP Deprecated: Caller ignored an error raised from SpecialRecentChanges::doMainQuery (max_statement_time exceeded)
T305215: 1.39.0-wmf.9 deployment blockers

Event Timeline

brennen triaged this task as Unbreak Now! priority.Apr 28 2022, 6:31 PM

brennen created this task.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 28 2022, 6:31 PM

@Ladsgroup thoughts here?

It is similar to/same as T304085: PHP Deprecated: Caller ignored an error raised from SpecialRecentChanges::doMainQuery (max_statement_time exceeded). Basically caught db error can cause issues like this (and catching db errors should be avoided). cc. @Krinkle

@Ladsgroup is the Lock wait timeout exceeded; try restarting transaction in WikiPage::updateRevisionOn really a blocker for this week train or may I move it out from the list of blockers? I don't quite understand whether the issue is critical or if it is merely a notification.

This is low frequency - I marked as blocker per the deprecation warning policy, but I don't think it's worth holding the train on. Removing as blocker.

brennen removed a parent task: T305216: 1.39.0-wmf.10 deployment blockers.May 3 2022, 3:37 PM

In T307132#7899159, @hashar wrote:

@Ladsgroup is the Lock wait timeout exceeded; try restarting transaction in WikiPage::updateRevisionOn really a blocker for this week train or may I move it out from the list of blockers? I don't quite understand whether the issue is critical or if it is merely a notification.

yeah, the deprecation error is red herring, it's not deprecation issue. It's caught db error.

Krinkle moved this task from Untriaged to Apr 2022 on the Wikimedia-production-error board.May 9 2022, 5:44 PM

Krinkle added a project: MediaWiki-Redirects.

The Lock wait timeout exceeded is a separate issue indeed that has user-impact and needs to be addressed in the revision backend.

The subject of this task is the fact that WikiPage.php or ApiMain.php is failing to recover correctly after that error. By the time the next query executes, the transaction state must be clean if/when code execution continues. While this is usually a genuie bug in the calling code, possibly similar to T304085 where we also found this to be an issue in the RecentChanges caller.

Additionally, given recent refactoring in Rdbms, it could also be a regression there, where perhaps WikiPage/ApiMain are correctly attempting to recover, but perhaps Rdbms is no longer handling this intention correctly and/or detecting something as dirty that a rollback doesn't clear.

I noticed that these deprecation warnings are still happening. Example log entry:

2022-11-14 02:48:38.096150 [e5bc6c94-7ba3-44ff-a244-fae9b90847bb] mw1428 enwiki 1.40.0-wmf.8 error WARNING: [e5bc6c94-7ba3-44ff-a244-fae9b90847bb] /w/api.php?action=query&format=json&list=recentchanges&rclimit=50&rcnamespace=0%7C3&rcprop=title%7Ctimestamp%7Cflags%7Cloginfo%7Coresscores%7Cparsedcomment%7Cuser%7Cids%7Ctags&rcshow=!bot%7Coresreview&rctoponly=true&rctype=edit%7Cnew   PHP Deprecated: Caller from MediaWiki\Block\DatabaseBlock::newLoad ignored an error originally raised from ApiQueryRecentChanges::run: [1969] Query execution was interrupted (max_statement_time exceeded) {"exception_url":"/w/api.php?action=query&format=json&list=recentchanges&rclimit=50&rcnamespace=0%7C3&rcprop=title%7Ctimestamp%7Cflags%7Cloginfo%7Coresscores%7Cparsedcomment%7Cuser%7Cids%7Ctags&rcshow=!bot%7Coresreview&rctoponly=true&rctype=edit%7Cnew","reqId":"e5bc6c94-7ba3-44ff-a244-fae9b90847bb","caught_by":"mwe_handler"} 
[Exception ErrorException] (/srv/mediawiki/php-1.40.0-wmf.8/includes/debug/MWDebug.php:381) PHP Deprecated: Caller from MediaWiki\Block\DatabaseBlock::newLoad ignored an error originally raised from ApiQueryRecentChanges::run: [1969] Query execution was interrupted (max_statement_time exceeded)
  #0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
  #1 /srv/mediawiki/php-1.40.0-wmf.8/includes/debug/MWDebug.php(381): trigger_error(string, integer)
  #2 /srv/mediawiki/php-1.40.0-wmf.8/includes/db/MWLBFactory.php(491): MWDebug::sendRawDeprecated(string, boolean, string)
  #3 [internal function]: MWLBFactory::logDeprecation(string)
  #4 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/TransactionManager.php(213): call_user_func(array, string)
  #5 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/Database.php(1331): Wikimedia\Rdbms\TransactionManager->assertTransactionStatus(Wikimedia\Rdbms\DatabaseMysqli, array, string)
  #6 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/Database.php(876): Wikimedia\Rdbms\Database->assertQueryIsCurrentlyAllowed(string, string)
  #7 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/Database.php(1648): Wikimedia\Rdbms\Database->query(string, string, integer)
  #8 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->select(array, array, string, string, array, array)
  #9 /srv/mediawiki/php-1.40.0-wmf.8/includes/libs/rdbms/database/DBConnRef.php(338): Wikimedia\Rdbms\DBConnRef->__call(string, array)
  #10 /srv/mediawiki/php-1.40.0-wmf.8/includes/block/DatabaseBlock.php(290): Wikimedia\Rdbms\DBConnRef->select(array, array, string, string, array, array)
  #11 /srv/mediawiki/php-1.40.0-wmf.8/includes/block/DatabaseBlock.php(886): MediaWiki\Block\DatabaseBlock::newLoad(User, integer, boolean, string)
  #12 /srv/mediawiki/php-1.40.0-wmf.8/includes/block/BlockManager.php(161): MediaWiki\Block\DatabaseBlock::newListFromTarget(User, string, boolean)
  #13 /srv/mediawiki/php-1.40.0-wmf.8/includes/user/User.php(1423): MediaWiki\Block\BlockManager->getUserBlock(User, WebRequest, boolean, boolean)
  #14 /srv/mediawiki/php-1.40.0-wmf.8/includes/user/User.php(1521): User->getBlockedStatus(boolean, boolean)
  #15 /srv/mediawiki/php-1.40.0-wmf.8/includes/block/BlockManager.php(544): User->getBlock()
  #16 /srv/mediawiki/php-1.40.0-wmf.8/includes/MediaWiki.php(781): MediaWiki\Block\BlockManager->trackBlockWithCookie(User, WebResponse)
  #17 /srv/mediawiki/php-1.40.0-wmf.8/includes/api/ApiMain.php(904): MediaWiki::preOutputCommit(DerivativeContext)
  #18 /srv/mediawiki/php-1.40.0-wmf.8/includes/api/ApiMain.php(849): ApiMain->executeActionWithErrorHandling()
  #19 /srv/mediawiki/php-1.40.0-wmf.8/api.php(90): ApiMain->execute()
  #20 /srv/mediawiki/php-1.40.0-wmf.8/api.php(45): wfApiMain()
  #21 /srv/mediawiki/w/api.php(3): require(string)
  #22 {main}

I made a model for this backtrace:

diff --git a/includes/api/ApiQueryRecentChanges.php b/includes/api/ApiQueryRecentChanges.php
index 30672ec2b9a..dbabf83aab1 100644
--- a/includes/api/ApiQueryRecentChanges.php
+++ b/includes/api/ApiQueryRecentChanges.php
@@ -418,6 +418,7 @@ class ApiQueryRecentChanges extends ApiQueryGeneratorBase {
 			$this->getConfig()->get( MainConfigNames::MaxExecutionTimeForExpensiveQueries )
 		);
 
+		$this->getDB()->query( "SELECT foo()" );
 		$hookData = [];
 		$count = 0;
 		/* Perform the actual query. */
diff --git a/includes/exception/MWExceptionHandler.php b/includes/exception/MWExceptionHandler.php
index 6aba8e7b7d7..64a6aed9b83 100644
--- a/includes/exception/MWExceptionHandler.php
+++ b/includes/exception/MWExceptionHandler.php
@@ -163,6 +163,7 @@ class MWExceptionHandler {
 		// to roll back some databases due to connection issues or exceptions.
 		// However, any sensible DB driver will roll back implicitly anyway.
 		try {
+			throw new DBError( null, "Can't roll back" );
 			$lbFactory = $services->getDBLoadBalancerFactory();
 			$lbFactory->rollbackPrimaryChanges( __METHOD__ );
 			$lbFactory->flushPrimarySessions( __METHOD__ );
diff --git a/includes/libs/rdbms/database/DatabaseMysqli.php b/includes/libs/rdbms/database/DatabaseMysqli.php
index 6b40e2e588b..0f5cd242955 100644
--- a/includes/libs/rdbms/database/DatabaseMysqli.php
+++ b/includes/libs/rdbms/database/DatabaseMysqli.php
@@ -45,7 +45,7 @@ class DatabaseMysqli extends DatabaseMysqlBase {
 		return new QueryStatus(
 			$res instanceof mysqli_result ? new MysqliResultWrapper( $this, $res ) : $res,
 			$this->affectedRows(),
-			$this->lastError(),
+			$this->lastError() ? 1969 : 0,
 			$this->lastErrno()
 		);
 	}
@@ -195,6 +195,7 @@ class DatabaseMysqli extends DatabaseMysqlBase {
 	 * @return int
 	 */
 	public function lastErrno() {
+		return $this->conn->errno ? 1969 : 0;
 		if ( $this->conn instanceof mysqli ) {
 			return $this->conn->errno;
 		} else {

This patch triggers the deprecation warning when ApiQueryRecentChanges is requested. An error occurs with code 1969, and then the rollback from ApiMain::handleException() fails, so that the transaction status remains in error when MediaWiki::preOutputCommit() is called.

Thanks, that helped a lot. I know where this is coming from but I don't know what to do. Basically it's in elseif ( $this->isKnownStatementRollbackError( $lastErrno ) ) { and if you change inside it to do $this->transactionManager->setTransactionError( $ex ); instead of $this->transactionManager->setTrxStatusIgnoredCause( $cause );, it'll start throwing [eb5271fb64c81a16c1242a4b] /w/api.php?action=query&list=recentchanges Wikimedia\Rdbms\DBTransactionStateError: Cannot execute query from MessageCache::loadFromDB(en)-big while transaction status is ERROR instead. And the code has this comment:

					// Allow legacy callers to ignore such errors via QUERY_IGNORE_DBO_TRX and
					// try/catch. However, a deprecation notice will be logged on the next query.

I assume we might want to ignore an error so we can style it but I don't understand exactly why it's called "legacy callers". The other part is that it's inside if ( $this->trxLevel() ) {} which means something is opening a transaction on a read query like this. We don't really need an implicit transaction in a read-only special page/api (repeatable read is useless, what exact use it can has?). If we remove that, it might fix the issue? I don't know how but if that sounds good to you, I can go and try it.

The legacy callers where mostly things using try/catch instead of INSERT...IGNORE or INSERT...ON DUPLICATE KEY UPDATE. Before statement timeouts, we didn't have many statement-rollback cases. There were still lock wait timeouts (when configured in mysql to be statement-rollback), but those general ruin the whole transaction (since there are generally incomplete writes).

REPEATABLE-READ is useful for constraint and foreign key consistency when data is read via multiple queries throughout the web requests, as MediaWiki heavily does.

It makes sense in some case to catch basic query timeouts, rollback, and continue. It also makes sense to catch and continue without rollback in some cases. If rollbackMasterChanges() is called immediately, then such notices should not arise. rollbackMasterChanges() tries to avoid throwing errors if it all possible.

I see a couple things to change here:

Basic query timeouts (not lock waits / deadlocks) should not flag the transaction state with a deprecation notice.
I see comments in MWExceptionHandler::rollbackPrimaryChanges about rollback throwing errors...they should probably be silenced (the only real failure for ROLLBACK is disconnect, which accomplishes the rollback anyway). This method should finish for all the handles so that transaction state flags get cleared (including this warning). Incomplete rollbacks, as in Tim's patch, will lead to TransactionStateError errors later on, due to transaction status flags not being cleared.

In T307132#8404551, @aaron wrote:

The legacy callers where mostly things using try/catch instead of INSERT...IGNORE or INSERT...ON DUPLICATE KEY UPDATE. Before statement timeouts, we didn't have many statement-rollback cases. There were still lock wait timeouts (when configured in mysql to be statement-rollback), but those general ruin the whole transaction (since there are generally incomplete writes).

REPEATABLE-READ is useful for constraint and foreign key consistency when data is read via multiple queries throughout the web requests, as MediaWiki heavily does.

Can you give a concrete example of not having implicit transaction breaking loading of recentchanges and the probability of it happening, plus the implications of it (would it corrupt any data for example?)

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])Open, Needs TriagePublicPRODUCTION ERRORActions