Page MenuHomePhabricator

"LogicException: We have a problem" from phpunit/…/RefreshSecondaryDataUpdateTest.php:
Closed, ResolvedPublic

Description

This is blocking the re-enablement of the "assert no runtime errors" step in CI, which checks that mw-error.log remains empty. This was accidentally removed a few months ago (T246358).

2020-03-20 18:06:30 32a44f17c9c0 wikidb-unittest_: [8a839d6559be93ca5d333927] [no req]   LogicException from line 103 of /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php: We have a problem
#0 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Stub/ReturnCallback.php(28): RefreshSecondaryDataUpdateTest->{closure}()
#1 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Matcher.php(152): PHPUnit\Framework\MockObject\Stub\ReturnCallback->invoke(PHPUnit\Framework\MockObject\Invocation)
#2 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/InvocationHandler.php(124): PHPUnit\Framework\MockObject\Matcher->invoked(PHPUnit\Framework\MockObject\Invocation)
#3 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/MockClass.php(42) : eval()'d code(24): PHPUnit\Framework\MockObject\InvocationHandler->invoke(PHPUnit\Framework\MockObject\Invocation)
#4 /workspace/src/includes/deferred/DeferredUpdates.php(417): Mock_DataUpdate_4db83a5f->doUpdate()
#5 /workspace/src/includes/deferred/RefreshSecondaryDataUpdate.php(97): DeferredUpdates::attemptUpdate(Mock_DataUpdate_4db83a5f, Wikimedia\Rdbms\LBFactorySimple)
#6 /workspace/src/includes/deferred/DeferredUpdates.php(417): RefreshSecondaryDataUpdate->doUpdate()
#7 /workspace/src/includes/deferred/DeferredUpdates.php(296): DeferredUpdates::attemptUpdate(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple)
#8 /workspace/src/includes/deferred/DeferredUpdates.php(233): DeferredUpdates::run(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple, class@anonymous�/workspace/src/includes/debug/logger/LogCapturingSpi.php0x7f475da01793, BufferingStatsdDataFactory, string)
#9 /workspace/src/includes/deferred/DeferredUpdates.php(150): DeferredUpdates::handleUpdateQueue(array, string, integer)
#10 /workspace/src/includes/deferred/DeferredUpdates.php(441): DeferredUpdates::doUpdates(string)
#11 /workspace/src/maintenance/Maintenance.php(716): DeferredUpdates::tryOpportunisticExecute(string)
#12 /workspace/src/includes/libs/rdbms/database/Database.php(3952): Maintenance::{closure}(integer, Wikimedia\Rdbms\DatabaseMysqli)
#13 /workspace/src/includes/libs/rdbms/database/Database.php(4311): Wikimedia\Rdbms\Database->runTransactionListenerCallbacks(integer)
#14 /workspace/src/includes/libs/rdbms/database/Database.php(4076): Wikimedia\Rdbms\Database->commit(string, string)
#15 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->endAtomic(string)
#16 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(629): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#17 /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php(140): Wikimedia\Rdbms\DBConnRef->endAtomic(string)
#18 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1408): RefreshSecondaryDataUpdateTest->testEnqueueOnFailure()
#19 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1028): PHPUnit\Framework\TestCase->runTest()
#20 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestResult.php(691): PHPUnit\Framework\TestCase->runBare()
#21 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(756): PHPUnit\Framework\TestResult->run(RefreshSecondaryDataUpdateTest)
#22 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php(418): PHPUnit\Framework\TestCase->run(PHPUnit\Framework\TestResult)
#23 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): MediaWikiIntegrationTestCase->run(PHPUnit\Framework\TestResult)
#24 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#25 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#26 /workspace/src/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(621): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#27 /workspace/src/vendor/phpunit/phpunit/src/TextUI/Command.php(200): PHPUnit\TextUI\TestRunner->doRun(PHPUnit\Framework\TestSuite, array, boolean)
#28 /workspace/src/tests/phpunit/phpunit.php(71): PHPUnit\TextUI\Command->run(array, boolean)
#29 /workspace/src/maintenance/doMaintenance.php(99): PHPUnitMaintClass->execute()
#30 /workspace/src/tests/phpunit/phpunit.php(130): require(string)
#31 {main}
2020-03-20 18:06:30 32a44f17c9c0 wikidb-unittest_: [8a839d6559be93ca5d333927] [no req]   LogicException from line 103 of /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php: We have a problem
#0 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Stub/ReturnCallback.php(28): RefreshSecondaryDataUpdateTest->{closure}()
#1 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Matcher.php(152): PHPUnit\Framework\MockObject\Stub\ReturnCallback->invoke(PHPUnit\Framework\MockObject\Invocation)
#2 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/InvocationHandler.php(124): PHPUnit\Framework\MockObject\Matcher->invoked(PHPUnit\Framework\MockObject\Invocation)
#3 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/MockClass.php(42) : eval()'d code(24): PHPUnit\Framework\MockObject\InvocationHandler->invoke(PHPUnit\Framework\MockObject\Invocation)
#4 /workspace/src/includes/deferred/DeferredUpdates.php(417): Mock_DataUpdate_4db83a5f->doUpdate()
#5 /workspace/src/includes/deferred/RefreshSecondaryDataUpdate.php(97): DeferredUpdates::attemptUpdate(Mock_DataUpdate_4db83a5f, Wikimedia\Rdbms\LBFactorySimple)
#6 /workspace/src/includes/deferred/DeferredUpdates.php(417): RefreshSecondaryDataUpdate->doUpdate()
#7 /workspace/src/includes/deferred/DeferredUpdates.php(296): DeferredUpdates::attemptUpdate(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple)
#8 /workspace/src/includes/deferred/DeferredUpdates.php(233): DeferredUpdates::run(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple, class@anonymous�/workspace/src/includes/debug/logger/LogCapturingSpi.php0x7f475da01793, BufferingStatsdDataFactory, string)
#9 /workspace/src/includes/deferred/DeferredUpdates.php(150): DeferredUpdates::handleUpdateQueue(array, string, integer)
#10 /workspace/src/includes/deferred/DeferredUpdates.php(441): DeferredUpdates::doUpdates(string)
#11 /workspace/src/maintenance/Maintenance.php(716): DeferredUpdates::tryOpportunisticExecute(string)
#12 /workspace/src/includes/libs/rdbms/database/Database.php(3952): Maintenance::{closure}(integer, Wikimedia\Rdbms\DatabaseMysqli)
#13 /workspace/src/includes/libs/rdbms/database/Database.php(4311): Wikimedia\Rdbms\Database->runTransactionListenerCallbacks(integer)
#14 /workspace/src/includes/libs/rdbms/database/Database.php(4076): Wikimedia\Rdbms\Database->commit(string, string)
#15 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->endAtomic(string)
#16 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(629): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#17 /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php(140): Wikimedia\Rdbms\DBConnRef->endAtomic(string)
#18 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1408): RefreshSecondaryDataUpdateTest->testEnqueueOnFailure()
#19 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1028): PHPUnit\Framework\TestCase->runTest()
#20 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestResult.php(691): PHPUnit\Framework\TestCase->runBare()
#21 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(756): PHPUnit\Framework\TestResult->run(RefreshSecondaryDataUpdateTest)
#22 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php(418): PHPUnit\Framework\TestCase->run(PHPUnit\Framework\TestResult)
#23 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): MediaWikiIntegrationTestCase->run(PHPUnit\Framework\TestResult)
#24 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#25 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#26 /workspace/src/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(621): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#27 /workspace/src/vendor/phpunit/phpunit/src/TextUI/Command.php(200): PHPUnit\TextUI\TestRunner->doRun(PHPUnit\Framework\TestSuite, array, boolean)
#28 /workspace/src/tests/phpunit/phpunit.php(71): PHPUnit\TextUI\Command->run(array, boolean)
#29 /workspace/src/maintenance/doMaintenance.php(99): PHPUnitMaintClass->execute()
#30 /workspace/src/tests/phpunit/phpunit.php(130): require(string)
#31 {main}
2020-03-20 18:06:30 32a44f17c9c0 wikidb-unittest_: [8a839d6559be93ca5d333927] [no req]   LogicException from line 103 of /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php: We have a problem
#0 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Stub/ReturnCallback.php(28): RefreshSecondaryDataUpdateTest->{closure}()
#1 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/Matcher.php(152): PHPUnit\Framework\MockObject\Stub\ReturnCallback->invoke(PHPUnit\Framework\MockObject\Invocation)
#2 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/InvocationHandler.php(124): PHPUnit\Framework\MockObject\Matcher->invoked(PHPUnit\Framework\MockObject\Invocation)
#3 /workspace/src/vendor/phpunit/phpunit/src/Framework/MockObject/MockClass.php(42) : eval()'d code(24): PHPUnit\Framework\MockObject\InvocationHandler->invoke(PHPUnit\Framework\MockObject\Invocation)
#4 /workspace/src/includes/deferred/DeferredUpdates.php(417): Mock_DataUpdate_4db83a5f->doUpdate()
#5 /workspace/src/includes/deferred/RefreshSecondaryDataUpdate.php(97): DeferredUpdates::attemptUpdate(Mock_DataUpdate_4db83a5f, Wikimedia\Rdbms\LBFactorySimple)
#6 /workspace/src/includes/deferred/DeferredUpdates.php(417): RefreshSecondaryDataUpdate->doUpdate()
#7 /workspace/src/includes/deferred/DeferredUpdates.php(296): DeferredUpdates::attemptUpdate(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple)
#8 /workspace/src/includes/deferred/DeferredUpdates.php(233): DeferredUpdates::run(RefreshSecondaryDataUpdate, Wikimedia\Rdbms\LBFactorySimple, class@anonymous�/workspace/src/includes/debug/logger/LogCapturingSpi.php0x7f475da01793, BufferingStatsdDataFactory, string)
#9 /workspace/src/includes/deferred/DeferredUpdates.php(150): DeferredUpdates::handleUpdateQueue(array, string, integer)
#10 /workspace/src/includes/deferred/DeferredUpdates.php(441): DeferredUpdates::doUpdates(string)
#11 /workspace/src/maintenance/Maintenance.php(716): DeferredUpdates::tryOpportunisticExecute(string)
#12 /workspace/src/includes/libs/rdbms/database/Database.php(3952): Maintenance::{closure}(integer, Wikimedia\Rdbms\DatabaseMysqli)
#13 /workspace/src/includes/libs/rdbms/database/Database.php(4311): Wikimedia\Rdbms\Database->runTransactionListenerCallbacks(integer)
#14 /workspace/src/includes/libs/rdbms/database/Database.php(4076): Wikimedia\Rdbms\Database->commit(string, string)
#15 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->endAtomic(string)
#16 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(629): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#17 /workspace/src/tests/phpunit/includes/deferred/RefreshSecondaryDataUpdateTest.php(140): Wikimedia\Rdbms\DBConnRef->endAtomic(string)
#18 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1408): RefreshSecondaryDataUpdateTest->testEnqueueOnFailure()
#19 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1028): PHPUnit\Framework\TestCase->runTest()
#20 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestResult.php(691): PHPUnit\Framework\TestCase->runBare()
#21 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(756): PHPUnit\Framework\TestResult->run(RefreshSecondaryDataUpdateTest)
#22 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php(418): PHPUnit\Framework\TestCase->run(PHPUnit\Framework\TestResult)
#23 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): MediaWikiIntegrationTestCase->run(PHPUnit\Framework\TestResult)
#24 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#25 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(597): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#26 /workspace/src/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(621): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#27 /workspace/src/vendor/phpunit/phpunit/src/TextUI/Command.php(200): PHPUnit\TextUI\TestRunner->doRun(PHPUnit\Framework\TestSuite, array, boolean)
#28 /workspace/src/tests/phpunit/phpunit.php(71): PHPUnit\TextUI\Command->run(array, boolean)
#29 /workspace/src/maintenance/doMaintenance.php(99): PHPUnitMaintClass->execute()
#30 /workspace/src/tests/phpunit/phpunit.php(130): require(string)
#31 {main}

Event Timeline

Anomie added a subscriber: Anomie.

This appears to be another one where code is verifying correct behavior in a failure case, and something along the way happens to be logging the exception that's characteristic of the failure being tested.

This instance appears to have been added in rMW1f4efc6c34aa: Add RefreshSecondaryDataUpdate and use it in DerivedPageDataUpdater, to test that a DeferredUpdate throwing an exception gets requeued as a job.

While T248195 was a weird edge case that shouldn't happen anyway, here we really do need to make sure this code doesn't break so just removing the test doesn't seem to be an option.

Thanks, that's good to know. While this is fairly rare, I do recall having handled this once or twice before.

The IntegrationTestCase class provides a setLogger method that can be used for this purpose, by stubbing out reports to a log channel, or (if desired) by mocking to an explicit expectation of it being logged. (example in ResourceLoaderTest).

@Krinkle can you update the priority for this task?

Change 584012 had a related patch set uploaded (by Nikki Nikkhoui; owner: Nikki Nikkhoui):
[mediawiki/core@master] Set logger to null in RefreshSecondaryataUpdateTest integration test

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

Krinkle triaged this task as High priority.Mar 27 2020, 4:54 PM

Change 584012 merged by jenkins-bot:
[mediawiki/core@master] Set logger to null in RefreshSecondaryataUpdateTest integration test

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