Page MenuHomePhabricator

DatabaseTest::testCriticalSectionErrorSelect fails locally, yet passes with php-xdebug enabled
Open, Needs TriagePublic

Description

Minimal test case:

vendor/bin/phpunit --configuration phpunit.xml.dist --filter 'testCriticalSectionErrorSelect' tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php
Using PHP 8.2.14
Running without MediaWiki settings because there are no integration tests
PHPUnit 9.6.16 by Sebastian Bergmann and contributors.

F                                                                   1 / 1 (100%)

Time: 00:00.017, Memory: 16.00 MB

There was 1 failure:

1) Wikimedia\Tests\Rdbms\DatabaseTest::testCriticalSectionErrorSelect
Failed asserting that exception of type "Wikimedia\Rdbms\DBTransactionStateError" is thrown.

FAILURES!
Tests: 1, Assertions: 3, Failures: 1.

The test in question:

DatabaseTest.php
	public function testCriticalSectionErrorSelect() {
		$this->expectException( DBTransactionStateError::class );

		$db = TestingAccessWrapper::newFromObject( $this->db );
		try {
			$this->corruptDbState( $db );
		} catch ( RuntimeException $e ) {
			$this->assertEquals( "Unexpected error", $e->getMessage() );
		}

		$db->query( "SELECT 1", __METHOD__ );
	}

Other info

When navigating to DatabaseTest.php in PhpStorm and running the test in isolation, it passes. Looking at the way PhpStorm runs this, it boils down to basically this:

$ php -dxdebug.mode=debug -dxdebug.client_host=127.0.0.1 -dxdebug.client_port=9003 -dxdebug.start_with_r vendor/bin/phpunit --configuration phpunit.xml.dist --filter "testCriticalSectionErrorSelect" --test-suffix DatabaseTest.php tests/phpunit/unit/includes/libs/rdbms/database

I've ruled out PhpStorm as a potential cause. Merely enabling xdebug without breakpoints or listening ports, is enough to make it pass:

php -dxdebug.mode=debug vendor/bin/phpunit --configuration phpunit.xml.dist --filter 'testCriticalSectionErrorSelect' tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php

This, of course, makes debugging it rather difficult.

Event Timeline

Given that php-xdebug, by definition, cannot be used to debug this problem, time to sprinkle some print, wfBacktrace, and var_dump:

diff --git a/includes/libs/rdbms/database/Database.php b/includes/libs/rdbms/database/Database.php
index d17e2631f9..ec0eea9e10 100644
--- a/includes/libs/rdbms/database/Database.php
+++ b/includes/libs/rdbms/database/Database.php
@@ -3117,6 +3117,7 @@ abstract class Database implements IDatabase, IMaintainableDatabase, LoggerAware
 				null, // emergency limit (default)
 				null, // emergency callback (default)
 				function () use ( $fname ) {
+					print "CriticalSectionProvider runs implicitExitCallback, defined by commenceCriticalSection, sets this->csmError\n" . wfBacktrace();
 					// Mark a critical section as having been aborted by an error
 					$e = new RuntimeException( "A critical section from {$fname} has failed" );
 					$this->csmError = $e;
diff --git a/tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php b/tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php
index d431a13980..5ec2209b7f 100644
--- a/tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php
+++ b/tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php
@@ -848,11 +848,12 @@ class DatabaseTest extends TestCase {
 	public function testCriticalSectionErrorSelect() {
 		$this->expectException( DBTransactionStateError::class );
 
-		$db = TestingAccessWrapper::newFromObject( $this->db );
+		$db = $this->db;
 		try {
 			$this->corruptDbState( $db );
 		} catch ( RuntimeException $e ) {
 			$this->assertEquals( "Unexpected error", $e->getMessage() );
+			print "\n" . __METHOD__ . " caught expected RuntimeException\n";
 		}
 
 		$db->query( "SELECT 1", __METHOD__ );
@@ -901,6 +902,7 @@ class DatabaseTest extends TestCase {
 	}
 
 	private function corruptDbState( $db ) {
+		$db = TestingAccessWrapper::newFromObject( $db );
 		$cs = $db->commenceCriticalSection( __METHOD__ );
 		$this->assertInstanceOf( CriticalSectionScope::class, $cs );
 		throw new RuntimeException( "Unexpected error" );
$ vendor/bin/phpunit --configuration phpunit.xml.dist --filter 'testCriticalSectionErrorSelect' tests/phpunit/unit/includes/libs/rdbms/database/DatabaseTest.php 
Using PHP 8.2.14
Running without MediaWiki settings because there are no integration tests
PHPUnit 9.6.16 by Sebastian Bergmann and contributors.

F                                                                   1 / 1 (100%)
Wikimedia\Tests\Rdbms\DatabaseTest::testCriticalSectionErrorSelect caught expected RuntimeException


Time: 00:00.017, Memory: 16.00 MB

There was 1 failure:

1) Wikimedia\Tests\Rdbms\DatabaseTest::testCriticalSectionErrorSelect
Failed asserting that exception of type "Wikimedia\Rdbms\DBTransactionStateError" is thrown.

FAILURES!
Tests: 1, Assertions: 3, Failures: 1.
CriticalSectionProvider runs implicitExitCallback, defined by commenceCriticalSection, sets this->csmError
Database.php line 3120 calls wfBacktrace()
CriticalSectionScope.php line 44 calls Wikimedia\Rdbms\Database->Wikimedia\Rdbms\{closure}()
- line - calls Wikimedia\RequestTimeout\CriticalSectionScope->__destruct()

So it seems that:

  • when php-xdebug is enabled, the CriticalSectionScope destructor is correctly called at the end of corruptDbState() right after throwing the exception.
  • when php-xdebug is disabled, the CriticalSectionScope hangs around way longer, until the end of the CLI process.

After some more debugging, I realized it is correlated with php-excimer being enabled.

Running the tests with php -n (which disables all extensions) also makes it pass. This suggests the CriticalSectionScope behaviour varies between the two implementations, in a way that is observable in this way. I don't know if that's an intentional or known difference in MediaWiki-libs-RequestTimeout

CriticalSectionScope is not meant to be alive until the end of the process. That's the whole point of it, to have scope lifetime.

I couldn't reproduce this, with PHP 8.2.15, xdebug disabled, and excimer locally compiled from the current git master.

We investigated further with @Krinkle today. Our results are follows:

We bisected XDebug and confirmed that the test passes with XDebug builds from prior to that PR being merged.

Unfortunately, this feature seems to be fundamentally incompatible with the RAII semantics that MediaWiki is relying on here—in order for this feature to work, the collected trace context must live at least as long as the exception it belongs to, which will inevitably break our expectations if the exception escapes the scope of an object that relies on RAII semantics.

Minimal reproducer:

<?php

class Test {
	public static function testDestructor() {
		$destructorRan = false;
		try {
			self::helper( $destructorRan );
		} catch ( UnexpectedValueException $e ) {
		}

		assert( $destructorRan );
	}

	private static function helper( &$destructorRan ) {
		$cb = static function () use ( &$destructorRan ) {
			$destructorRan = true;
		};
		$class = new class ( $cb ) {
			private $cb;

			public function __construct( $cb ) {
				$this->cb = $cb;
			}

			public function __destruct() {
				( $this->cb )();
			}
		};

		throw new UnexpectedValueException( 'e' );
	}
}

Test::testDestructor();

The above script fails with XDebug loaded and xdebug.mode containing develop, completes successfully otherwise.

Looks like this already got reported as https://bugs.xdebug.org/view.php?id=2222. The author does not seem to be particularly swayed by it though...

I've found another example of Xdebug's object retention causing tests to fail. As of late, I can't get composer phpunit tests/phpunit/includes/language/MessageTest.php to pass locally.

Context:

There was 1 error:

1) MessageTest::testWfMessageParams
LogicException: Parser state cleared while parsing. Did you call Parser::parse recursively? Lock is held by: #0 /mediawiki/includes/parser/Parser.php(933): MediaWiki\Parser\Parser->lock()
#1 /mediawiki/includes/parser/Parser.php(5022): MediaWiki\Parser\Parser->preprocess('{{PLURAL:$3|You...', Object(MediaWiki\Page\PageReferenceValue), Object(MediaWiki\Parser\ParserOptions))
#2 /mediawiki/includes/language/MessageParser.php(121): MediaWiki\Parser\Parser->transformMsg('{{PLURAL:$3|You...', Object(MediaWiki\Parser\ParserOptions), Object(MediaWiki\Page\PageReferenceValue))
#3 /mediawiki/includes/language/Message/Message.php(1479): MediaWiki\Language\MessageParser->transform('{{PLURAL:$3|You...', true, Object(LanguageEn), Object(MediaWiki\Page\PageReferenceValue))
#4 /mediawiki/includes/language/Message/Message.php(1059): MediaWiki\Message\Message->transformText('{{PLURAL:$3|You...')
#5 /mediawiki/includes/language/Message/Message.php(1107): MediaWiki\Message\Message->format('text')
#6 /mediawiki/tests/phpunit/includes/language/MessageTest.php(221): MediaWiki\Message\Message->text()
#7 …
#17 {main}

/mediawiki/includes/parser/Parser.php:6501
/mediawiki/includes/parser/Parser.php:933
/mediawiki/includes/parser/Parser.php:5022
/mediawiki/includes/language/MessageParser.php:121
/mediawiki/includes/language/Message/Message.php:1479
/mediawiki/includes/language/Message/Message.php:1059
/mediawiki/includes/language/Message/Message.php:1107
/mediawiki/tests/phpunit/includes/language/MessageTest.php:246

In MessageTest::testWfMessageParams we have:

		$this->assertSame(
			'You have foo (bar).',
			wfMessage( 'new-messages', 'foo', 'bar' )->text()
		);
		$this->assertSame(
		 	'You have foo (bar).',
		 	wfMessage( 'new-messages', [ 'foo', 'bar' ] )->text()
		);

And the error is reporting that when the second Message::text call starts (MessageTest.php:246), the lock from the first Message::text() call (MessageTest.php:221) is still being held somehow.

This is of course completely impossible, because the lock doesn't even leave the private function scope

Message::text -> MessageParser ->Parser::preprocess

Parser.php
public function preprocess( $text ) {
	$magicScopeVariable = $this->lock();
	// …
	return $text;
}

protected function lock() {
	if ( $this->mInParse ) {
		throw new LogicException( "Parser state cleared. […] Lock is held by: " . $this->mInParse );
	}
	$this->mInParse = ( new RuntimeException )->getTraceAsString();
	return new ScopedCallback( function () {
		$this->mInParse = false;
	} );
}

But, similar to the Rdbms test failure that this task started with, it turns out that I still had Xdebug enabled, which in turn means a bunch of objects around this exception are being held in memory with their destructor callback held back.

debugging Parser.php
--- a/includes/parser/Parser.php
+++ b/includes/parser/Parser.php
@@ -6506,12 +6506,13 @@ class Parser {
        // we can print the lock owner's backtrace for easier debugging
        $e = new RuntimeException;
        $this->mInParse = $e->getTraceAsString();
+       $caller = $e->getTrace()[6]['file'] . ':' . $e->getTrace()[6]['line'];
 
-       $recursiveCheck = new ScopedCallback( function () {
+       $recursiveCheck = new ScopedCallback( function () use ( $caller ) {
+       print "Parser::lock start for $caller\n";
            $this->mInParse = false;
        } );
    }
PHPUnit 9.6.21 by Sebastian Bergmann and contributors.

E                                                                   1 / 1 (100%)Parser::lock start for /mediawiki/tests/phpunit/includes/language/MessageTest.php:221


Time: 00:00.109, Memory: 51.00 MB

There was 1 error:

1) MessageTest::testWfMessageParams
LogicException: Parser state cleared while parsing. Did you call Parser::parse recursively? Lock is held by: #0 /mediawiki/includes/parser/Parser.php(933): MediaWiki\Parser\Parser->lock()
#1 /mediawiki/includes/parser/Parser.php(5022): MediaWiki\Parser\Parser->preprocess('{{PLURAL:$3|You...', Object(MediaWiki\Page\PageReferenceValue), Object(MediaWiki\Parser\ParserOptions))
#2 /mediawiki/includes/language/MessageParser.php(121): MediaWiki\Parser\Parser->transformMsg('{{PLURAL:$3|You...', Object(MediaWiki\Parser\ParserOptions), Object(MediaWiki\Page\PageReferenceValue))
#3 /mediawiki/includes/language/Message/Message.php(1479): MediaWiki\Language\MessageParser->transform('{{PLURAL:$3|You...', true, Object(LanguageEn), Object(MediaWiki\Page\PageReferenceValue))
#4 /mediawiki/includes/language/Message/Message.php(1059): MediaWiki\Message\Message->transformText('{{PLURAL:$3|You...')
#5 /mediawiki/includes/language/Message/Message.php(1107): MediaWiki\Message\Message->format('text')
#6 /mediawiki/tests/phpunit/includes/language/MessageTest.php(221): MediaWiki\Message\Message->text()
#7 …
#17 {main}

/mediawiki/includes/parser/Parser.php:6501
/mediawiki/includes/parser/Parser.php:933
/mediawiki/includes/parser/Parser.php:5022
/mediawiki/includes/language/MessageParser.php:121
/mediawiki/includes/language/Message/Message.php:1479
/mediawiki/includes/language/Message/Message.php:1059
/mediawiki/includes/language/Message/Message.php:1107
/mediawiki/tests/phpunit/includes/language/MessageTest.php:246

ERRORS!
Tests: 1, Assertions: 5, Errors: 1.
Parser::lock end for /mediawiki/tests/phpunit/includes/language/MessageTest.php:221

Note how the destructor does run, but not until the very end of the PHPUnit process.

I've found another example of Xdebug's object retention causing tests to fail. As of late, I can't get composer phpunit tests/phpunit/includes/language/MessageTest.php to pass locally.

FTR, AFAICT this is the same issue as T366986 (reported by various people since June 2024), though nobody over there managed to figure out that it’s due to xdebug (we were all very confused about the inexplicable destructor behavior).