Page MenuHomePhabricator

DeferredUpdates hides exceptions
Closed, ResolvedPublic

Description

MediaWiki	1.29.0-rc.0 (4e4d48d)
PHP	7.1.1 (apache2handler)
MariaDB	10.1.21-MariaDB
ICU	57.1

While investigating some missing data updates during a DeferredUpdates execution, I found that any DeferrableUpdate that throws an exception isn't logged and a discovery of correlating issues is made very difficult.

\DeferredUpdates::addUpdate( new TestStorage( 'test 1', true ) );
\DeferredUpdates::addUpdate( new TestStorage( 'test 2' ) );
WikiPage::doEditUpdates: Using prepared edit...
Saved in parser cache with key mw-29-00:pcache:idhash:13-0!*!0!*!en!*!* and timestamp 20170619224136 and revision id 110
Title::getRestrictionTypes: applicable restrictions to [[Test]] are {edit,move}

MediaWiki::preOutputCommit: pre-send deferred updates completed
[cookie] setcookie: "cpPosTime", "1497912097.112", "1497912157", "/", "", "", "1"
[DBReplication] Wikimedia\Rdbms\ChronologyProtector::shutdownLB: DB 'localhost' touched

MediaWiki::preOutputCommit: LBFactory shutdown completed
OutputPage::sendCacheControl: private caching;  **
[test] SMW\TestStorage::doUpdate before exception test 1
Request ended normally
[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database 'localhost'.
[DBConnection] Closing connection to database 'localhost'.
class TestStorage implements DeferrableUpdate {

	private $origin;
	private $throwException;

	public function __construct( $origin, $throwException = false ) {
		$this->origin = $origin;
		$this->throwException = $throwException;
	}

	public function doUpdate() {

		$msg = $this->throwException ? 'exception' : '';

		wfDebugLog( 'test', __METHOD__ . " before $msg $this->origin" );

		if ( $this->throwException ) {
			throw new \Exception( "DeferrableUpdate forced exception" );
		}

		wfDebugLog( 'test', __METHOD__ . " after $msg $this->origin" );
	}

}

As demonstrated in the output, [test] SMW\TestStorage::doUpdate before exception test 1 is logged before an exception is thrown put anything after that is hidden and silent.

error_reporting(E_STRICT|E_ALL);
ini_set("display_errors", 1);
$wgShowExceptionDetails = true;
$wgDevelopmentWarnings = true;
$wgShowSQLErrors = true;
$wgDebugDumpSql  = false;
$wgShowDBErrorBacktrace = true;

$wgDebugLogFile = ".../debug-{$wgDBname}.log";

Event Timeline

@Seb35 Maybe something you want to have look at a convenient time?

Kghbln subscribed.

Perhaps related to the re-emerging failure of category propagation as described in T168723?

Change 361780 had a related patch set uploaded (by Legoktm; owner: Legoktm):
[mediawiki/core@master] Always log exceptions in rollbackMasterChangesAndLog()

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

Change 361787 had a related patch set uploaded (by Seb35; owner: Seb35):
[mediawiki/core@master] Add logging for exceptions inside DerrableUpdate

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

I didn’t see the notification earlier -- in fact it was in my bunch of emails, but I would have expected that a direct mention shows something in Phabricator like in MediaWiki/Echo, seems it’s not the case.

My patch is a quick hack to display the exception in the debug log. Just see @Legoktm has proposed another solution, probably better than my quick hack.

Change 361787 abandoned by Seb35:
Add logging for exceptions inside DerrableUpdate

Reason:
The patch from Legoktm in I8739051f824a455ba669344184c3b11ac95cb561 has a better quality/integration into MediaWiki error management.

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

Change 362599 had a related patch set uploaded (by Chad; owner: Aaron Schulz):
[mediawiki/core@REL1_29] Always log exceptions in rollbackMasterChangesAndLog()

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

Change 361780 merged by jenkins-bot:
[mediawiki/core@master] Always log exceptions in rollbackMasterChangesAndLog()

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

Change 362599 merged by jenkins-bot:
[mediawiki/core@REL1_29] Always log exceptions in rollbackMasterChangesAndLog()

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