Database::onTransactionCommitOrIdle callbacks should either execute or be cleaned up between tests (causes confusing fatal at end of PHP process)
Open, Needs TriagePublic
Actions

Assigned To

None

Authored By

	Umherirrender
	Dec 13 2023, 6:29 PM

Description

Seen a phpunit ending like this, without notice about what test cases are failing makes it hard to find a issue.

https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php82-noselenium-docker/161/console

............................................................. 1525 / 1610 ( 94%)
........................................................IEEEE 1586 / 1610 ( 98%)
EEEEES

You should really speed up these slow tests (>50ms)...
 1. 1996ms to run ResourcesTest::testResourceFiles
 2. 901ms to run SpecialPageFatalTest::testSpecialPageDoesNotFatal
 3. 763ms to run ResourcesTest::testRespond with data set #122
 4. 757ms to run ResourcesTest::testRespond with data set #371
 5. 529ms to run MediaWiki\\Skins\\Vector\\Tests\\Structure\\PerformanceBudgetTest::testTotalModulesSize with data set "vector-2022"
 6. 528ms to run MediaWiki\\Skins\\Vector\\Tests\\Structure\\PerformanceBudgetTest::testTotalModulesSize with data set "vector"
 7. 389ms to run ResourcesTest::testRespond with data set #225
 8. 380ms to run ResourcesTest::testStyleMedia
 9. 311ms to run ResourcesTest::testRespond with data set #257
 10. 306ms to run ResourcesTest::testRespond with data set #474
...and there are 85 more above your threshold hidden from view
Cannot execute query from CloneDatabase::destroy while session state is out of sync
Script phpunit handling the phpunit event returned with error code 2
Script @phpunit -c tests/phpunit/suite.xml was called via phpunit:entrypoint
INFO:quibble.commands:<<< Finish: PHPUnit extensions suite (with database), in 24.436 s

The good news, the mw-error.log shows a exception, but without a file or line number about the failure.

2023-12-13 15:18:50 fabae32060bd wikidb-unittest_: [a56a6b2a597393734610775c] [no req]   PHPUnit\Framework\Error\Deprecated: Using ${var} in strings is deprecated, use {$var} instead
#0 /workspace/src/includes/AutoLoader.php(221): PHPUnit\Util\ErrorHandler->__invoke()
#1 /workspace/src/includes/AutoLoader.php(221): require()
#2 /workspace/src/extensions/TimedMediaHandler/includes/WebVideoTranscode/WebVideoTranscode.php(1386): AutoLoader::autoload()
#3 /workspace/src/extensions/TimedMediaHandler/includes/WebVideoTranscode/WebVideoTranscode.php(1197): MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::updateJobQueue()
#4 /workspace/src/extensions/TimedMediaHandler/includes/Hooks.php(304): MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::startJobQueue()
#5 /workspace/src/includes/HookContainer/HookContainer.php(161): MediaWiki\TimedMediaHandler\Hooks->onFileUpload()

The fix for that is 2ca1b0e465aae579c57c470b38861c5a46c18541

The mw-debug-cli.log shows more infos:

[DeferredUpdates] Deferred update 'MediaWiki\Deferred\AutoCommitUpdate_LocalFile::recordUpload3' failed to run.
#0 /workspace/src/includes/AutoLoader.php(221): PHPUnit\Util\ErrorHandler->__invoke()
#1 /workspace/src/includes/AutoLoader.php(221): require()
#2 /workspace/src/extensions/TimedMediaHandler/includes/WebVideoTranscode/WebVideoTranscode.php(1386): AutoLoader::autoload()
#3 /workspace/src/extensions/TimedMediaHandler/includes/WebVideoTranscode/WebVideoTranscode.php(1197): MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::updateJobQueue()
#4 /workspace/src/extensions/TimedMediaHandler/includes/Hooks.php(304): MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::startJobQueue()
#5 /workspace/src/includes/HookContainer/HookContainer.php(161): MediaWiki\TimedMediaHandler\Hooks->onFileUpload()

and it seems the database is in bad state

[PHPUnit] ERROR in test ApiUploadVideoTest::testUploadVideoFiles with data set #1 (array('video/webm', '/workspace/src/extensions/Tim...8.webm', 699018, 1080, 608, 'VIDEO', 522142, 29.97)): Cannot execute Wikimedia\Rdbms\Database::selectDomain critical section while session state is out of sync.

A critical section from Wikimedia\Rdbms\Database::runOnTransactionIdleCallbacks has failed
#0 /workspace/src/vendor/wikimedia/request-timeout/src/CriticalSectionScope.php(44): Wikimedia\Rdbms\Database->Wikimedia\Rdbms\{closure}()
#1 /workspace/src/includes/libs/rdbms/database/Database.php(1940): Wikimedia\RequestTimeout\CriticalSectionScope->__destruct()
#2 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->onTransactionCommitOrIdle()
#3 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(635): Wikimedia\Rdbms\DBConnRef->__call()
#4 /workspace/src/includes/filerepo/file/LocalFile.php(2053): Wikimedia\Rdbms\DBConnRef->onTransactionCommitOrIdle()
#5 /workspace/src/includes/filerepo/file/LocalFile.php(1673): LocalFile->recordUpload3()
#6 /workspace/src/includes/upload/UploadBase.php(924): LocalFile->upload()

[PHPUnit] ERROR in test ApiUploadVideoTest::testValidCovers: Cannot execute Wikimedia\Rdbms\Database::selectDomain critical section while session state is out of sync.

A critical section from Wikimedia\Rdbms\Database::runOnTransactionIdleCallbacks has failed
#0 /workspace/src/vendor/wikimedia/request-timeout/src/CriticalSectionScope.php(44): Wikimedia\Rdbms\Database->Wikimedia\Rdbms\{closure}()
#1 /workspace/src/includes/libs/rdbms/database/Database.php(1940): Wikimedia\RequestTimeout\CriticalSectionScope->__destruct()
#2 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->onTransactionCommitOrIdle()
#3 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(635): Wikimedia\Rdbms\DBConnRef->__call()

[PHPUnit] ERROR in test VideoTranscodeTest::testValidCovers: Cannot execute Wikimedia\Rdbms\Database::selectDomain critical section while session state is out of sync.

A critical section from Wikimedia\Rdbms\Database::runOnTransactionIdleCallbacks has failed
#0 /workspace/src/vendor/wikimedia/request-timeout/src/CriticalSectionScope.php(44): Wikimedia\Rdbms\Database->Wikimedia\Rdbms\{closure}()
#1 /workspace/src/includes/libs/rdbms/database/Database.php(1940): Wikimedia\RequestTimeout\CriticalSectionScope->__destruct()
#2 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(119): Wikimedia\Rdbms\Database->onTransactionCommitOrIdle()
#3 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(635): Wikimedia\Rdbms\DBConnRef->__call()
#4 /workspace/src/includes/filerepo/file/LocalFile.php(2053): Wikimedia\Rdbms\DBConnRef->onTransactionCommitOrIdle()
#5 /workspace/src/includes/filerepo/file/LocalFile.php(1673): LocalFile->recordUpload3()

[PHPUnit] Start test LegacyParserTest_TimedMediaHandler_1__parserTests
[PHPUnit] ERROR in test LegacyParserTest_TimedMediaHandler_1__parserTests: Cannot execute query from CloneDatabase::destroy while session state is out of sync
[PHPUnit] Start test ParsoidParserTest_TimedMediaHandler_1__parserTests
[PHPUnit] Skipped test ParsoidParserTest_TimedMediaHandler_1__parserTests: Test skipped because of an error in setUp method

Not sure if there is anything to make better, but want to tell about this here. Putting the teardown into a try/catch could be a way, but not sure if the database state is better and not mixed up between real and test

Related Objects

Mentioned Here: rETMH2ca1b0e465aa: Using ${var} in strings is deprecated, use {$var} instead

Event Timeline

Umherirrender created this task.Dec 13 2023, 6:29 PM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 13 2023, 6:29 PM

I don't think this is related to deferred updates. The deferred update happens to be scheduled from inside a database idle callback.

Some test -> LocalFile::recordUpload3 -> Database::onTransactionCommitOrIdle (subscribes to db commit).

Then, my guess is, the test ends without ever committing the database transaction, so it hangs around until longer. Until, eventually PHPUnit is done and we exit the PHP command-line process, and objects start being destructed. Your stacktrace shows CriticalSectionScope->__destruct() is part of the chain, which is what then informs Rdbms that is has one last chance to run idle callbacks, and takes its chance to do so.

When the callback is invoked, and LocalFile::recordUpload3 happens to use that callback to run a deferred update.

That deferred update then tries to interact with the database, long after it has been destroyed, hence Cannot execute query from CloneDatabase::destroy while session state is out of sync. However, that is merely the last in a chain of failures. The problem is that the "idle" callback was allowed to outlive the specific unit test that queued it. These should either run or get removed between tests.

Krinkle renamed this task from Deferred update failure in phpunit is not show in the list of failed tests at the end and brings database state out of sync to Database::onTransactionCommitOrIdle callbacks should either execute or be cleaned up between tests (causes confusing fatal at end of PHP process).Dec 14 2023, 11:10 PM

Krinkle moved this task from Inbox to PHPUnit on the MediaWiki-Core-Tests board.

Umherirrender unsubscribed.Feb 11 2024, 12:07 AM

Database::onTransactionCommitOrIdle callbacks should either execute or be cleaned up between tests (causes confusing fatal at end of PHP process)Open, Needs TriagePublicActions

Description

Related Objects

Event Timeline

Database::onTransactionCommitOrIdle callbacks should either execute or be cleaned up between tests (causes confusing fatal at end of PHP process)
Open, Needs TriagePublic
Actions