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

Krinkle created this task.Mar 20 2020, 6:24 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 20 2020, 6:24 PM
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.

Krinkle added a comment.EditedMar 20 2020, 10:41 PM

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
Pchelolo closed this task as Resolved.Mar 27 2020, 7:51 PM

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

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