All PageTriage patches are getting rejected by jenkins/zuul during gate-and-submit jobs after a +2 code review, due to 8 ORES unit test rounding errors.
Started a couple days ago. I wonder what changed? Maybe ORES upstream is outputting more significant digits now?
Anyway the simplest fix is to probably add `round()` somewhere in the unit test code.
```
```
```
lines=15
07:22:36 There were 8 failures:
07:22:36
07:22:36 1) ORES\Tests\Api\ApiIntegrationTest::testListRecentChanges_getOresScores
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'damaging' => Array (...)
07:22:36 'goodfaith' => Array (
07:22:36 'true' => 0.7
07:22:36 - 'false' => 0.3
07:22:36 + 'false' => 0.30000000000000004
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Api/ApiIntegrationTest.php:125
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [MessageCache] [debug] MessageCache using store {class} {"class":"HashBagOStuff"}
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [CentralAuth] [debug] Loading state for global user {user} from DB {"user":"TestUser 606748.1d7"}
07:22:36 [CentralAuth] [debug] Loading attached wiki list for global user TestUser 606748.1d7 from DB []
07:22:36 [CentralAuth] [debug] Loading groups for global user {user} {"user":"TestUser 606748.1d7"}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:centralauth-user:d24c55bc8b9c004149ecbcdb7025ab39): miss, new value computed []
07:22:36 [CentralAuth] [debug] Loading CentralAuthUser for user {user} from cache object {"user":"TestUser 606748.1d7"}
07:22:36 [CentralAuth] [debug] Loading state for global user {user} from DB {"user":"TestUser MediaWikiIntegrationTestCase 606748.1d8"}
07:22:36 [CentralAuth] [debug] Loading attached wiki list for global user TestUser MediaWikiIntegrationTestCase 606748.1d8 from DB []
07:22:36 [CentralAuth] [debug] Loading groups for global user {user} {"user":"TestUser MediaWikiIntegrationTestCase 606748.1d8"}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:centralauth-user:7fd718912fcc007e12357b629a9c0348): miss, new value computed []
07:22:36 [CentralAuth] [debug] Loading CentralAuthUser for user {user} from cache object {"user":"TestUser MediaWikiIntegrationTestCase 606748.1d8"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [ContentHandler] [info] Registered handler for wikitext: WikitextContentHandler []
07:22:36 [objectcache] [debug] MainObjectStash using store {class} {"class":"HashBagOStuff"}
07:22:36 [ParserCache] [debug] Creating ParserCache instance for pcache []
07:22:36 [wfDebug] [debug] ParserFactory: using default preprocessor {"private":false}
07:22:36 [localisation] [debug] LocalisationCache::isExpired(en): cache missing, need to make one []
07:22:36 [ParserCache] [debug] Creating RevisionOutputCache instance for parsoid []
07:22:36 [ParserCache] [debug] Creating ParserCache instance for parsoid []
07:22:36 [MessageCache] [debug] MessageCache using store {class} {"class":"HashBagOStuff"}
07:22:36 [UserOptionsManager] [debug] Loading options from database {"user_id":57}
07:22:36 [localisation] [debug] LocalisationCache::isExpired(en): cache missing, need to make one []
07:22:36 [objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:content_models:wikidb-unittest_","lag":0,"age":0.089073896408081055,"walltime":0.0015170574188232422}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:content_models:wikidb-unittest_): miss, new value computed []
07:22:36 [objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:slot_roles:wikidb-unittest_","lag":0,"age":0.091667890548706055,"walltime":0.0014579296112060547}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:slot_roles:wikidb-unittest_): miss, new value computed []
07:22:36 [EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.revision-create"}
07:22:36 [EventStreamConfig] [warning] Stream 'mediawiki.revision-create' does not match any `stream` in stream config []
07:22:36 [EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.revision-create. destination_event_service is not configured. []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-restrictions:v1:2:2): miss, new value computed []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [wfDebug] [debug] User::getBlockedStatus: checking blocked status for TestUser MediaWikiIntegrationTestCase 606748.1d8 {"private":false}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #29592 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #29592, processing time: 0.00014305114746094 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #50942 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #50942, processing time: 0.0018980503082275 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_RecentChange::notifyNew #22609 []
07:22:36 [ORES] [debug] Processing edit {revid} {"revid":2}
07:22:36 [ORES] [debug] Job pushed for {revid} {"revid":2}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_RecentChange::notifyNew #22609, processing time: 0.0084030628204346 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_FlaggedRevsHooks::autoMarkPatrolled #51162 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_FlaggedRevsHooks::autoMarkPatrolled #51162, processing time: 0.0022459030151367 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started UserEditCountUpdate #45661 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended UserEditCountUpdate #45661, processing time: 0.0014519691467285 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #34039 []
07:22:36 [SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"ORESApiIntegrationTestPage"}
07:22:36 [SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"ORESApiIntegrationTestPage"}
07:22:36 [ParserCache] [debug] Saved in parser cache {"name":"pcache","key":"wikidb-unittest_:pcache:idhash:2-0!canonical","cache_time":"20220919142159","rev_id":2}
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-content-model:2): miss, new value computed []
07:22:36 [EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.page-create"}
07:22:36 [EventStreamConfig] [warning] Stream 'mediawiki.page-create' does not match any `stream` in stream config []
07:22:36 [EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.page-create. destination_event_service is not configured. []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #34039, processing time: 0.0066571235656738 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started RefreshSecondaryDataUpdate #45661 []
07:22:36 [wfDebug] [debug] BacklinkCache::queryLinks: got results from DB {"private":false}
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended RefreshSecondaryDataUpdate #45661, processing time: 0.02521800994873 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #41625 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #41625, processing time: 0.00022315979003906 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started SearchUpdate #29592 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended SearchUpdate #29592, processing time: 0.0024318695068359 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #45726 []
07:22:36 [wfDebug] [debug] Article::getContext called and $mContext is null. Return RequestContext::getMain() {"private":false}
07:22:36 [UserOptionsManager] [debug] Loading options from database {"user_id":1}
07:22:36 [Parser] [debug] Parser::setOutputFlag: set user-signature flag on 'ORESApiIntegrationTestPage'; User signature detected []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #45726, processing time: 0.020657062530518 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #20751 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #20751, processing time: 0.0040419101715088 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #40818 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #40818, processing time: 0.00010514259338379 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #42411 []
07:22:36 [EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.page-properties-change"}
07:22:36 [EventStreamConfig] [warning] Stream 'mediawiki.page-properties-change' does not match any `stream` in stream config []
07:22:36 [EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.page-properties-change. destination_event_service is not configured. []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #42411, processing time: 0.00069904327392578 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started SiteStatsUpdate #28009 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended SiteStatsUpdate #28009, processing time: 0.0009009838104248 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_EchoNotificationMapper::insert #28391 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_EchoNotificationMapper::insert #28391, processing time: 0.0019650459289551 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_EchoNotificationMapper::insert #47741 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_EchoNotificationMapper::insert #47741, processing time: 0.0020530223846436 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::onLinksUpdateComplete #37491 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::onLinksUpdateComplete #37491, processing time: 7.2956085205078E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #48488 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #48488, processing time: 6.2942504882812E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started CdnCacheUpdate #28668 []
07:22:36 [squid] [info] CdnCacheUpdate::purge: http://127.0.0.1:9413/index.php/ORESApiIntegrationTestPage http://127.0.0.1:9413/index.php?title=ORESApiIntegrationTestPage&action=history http://127.0.0.1:9413/index.php/Talk:ORESApiIntegrationTestPage http://127.0.0.1:9413/index.php?title=Talk:ORESApiIntegrationTestPage&action=history {"private":false}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended CdnCacheUpdate #28668, processing time: 0.00021815299987793 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Storage\PageUpdater->saveRevision #23111 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Storage\PageUpdater->saveRevision #23111, processing time: 0.00017714500427246 []
07:22:36 [wfDebug] [debug] ApiMain::setCacheMode: downgrading cache mode 'public' to 'anon-public-user-private' due to uselang=user {"private":false}
07:22:36 [wfDebug] [debug] ApiMain::setCacheMode: setting cache mode anon-public-user-private {"private":false}
07:22:36 ===
07:22:36
07:22:36 2) ORES\Tests\Api\ApiIntegrationTest::testListWatchlist_getOresScores
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'damaging' => Array (...)
07:22:36 'goodfaith' => Array (
07:22:36 'true' => 0.7
07:22:36 - 'false' => 0.3
07:22:36 + 'false' => 0.30000000000000004
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Api/ApiIntegrationTest.php:260
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [MessageCache] [debug] MessageCache using store {class} {"class":"HashBagOStuff"}
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [CentralAuth] [debug] Loading state for global user {user} from DB {"user":"TestUser 606748.1e6"}
07:22:36 [CentralAuth] [debug] Loading attached wiki list for global user TestUser 606748.1e6 from DB []
07:22:36 [CentralAuth] [debug] Loading groups for global user {user} {"user":"TestUser 606748.1e6"}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:centralauth-user:33c4a5f1f33e978e195d53cc221722d2): miss, new value computed []
07:22:36 [CentralAuth] [debug] Loading CentralAuthUser for user {user} from cache object {"user":"TestUser 606748.1e6"}
07:22:36 [CentralAuth] [debug] Loading state for global user {user} from DB {"user":"TestUser MediaWikiIntegrationTestCase 606748.1e7"}
07:22:36 [CentralAuth] [debug] Loading attached wiki list for global user TestUser MediaWikiIntegrationTestCase 606748.1e7 from DB []
07:22:36 [CentralAuth] [debug] Loading groups for global user {user} {"user":"TestUser MediaWikiIntegrationTestCase 606748.1e7"}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:centralauth-user:648aec7ff14baab60403b818be75705e): miss, new value computed []
07:22:36 [CentralAuth] [debug] Loading CentralAuthUser for user {user} from cache object {"user":"TestUser MediaWikiIntegrationTestCase 606748.1e7"}
07:22:36 [localisation] [debug] LocalisationCache using store LCStoreNull []
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 [ContentHandler] [info] Registered handler for wikitext: WikitextContentHandler []
07:22:36 [objectcache] [debug] MainObjectStash using store {class} {"class":"HashBagOStuff"}
07:22:36 [ParserCache] [debug] Creating ParserCache instance for pcache []
07:22:36 [wfDebug] [debug] ParserFactory: using default preprocessor {"private":false}
07:22:36 [localisation] [debug] LocalisationCache::isExpired(en): cache missing, need to make one []
07:22:36 [ParserCache] [debug] Creating RevisionOutputCache instance for parsoid []
07:22:36 [ParserCache] [debug] Creating ParserCache instance for parsoid []
07:22:36 [MessageCache] [debug] MessageCache using store {class} {"class":"HashBagOStuff"}
07:22:36 [UserOptionsManager] [debug] Loading options from database {"user_id":67}
07:22:36 [localisation] [debug] LocalisationCache::isExpired(en): cache missing, need to make one []
07:22:36 [objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:content_models:wikidb-unittest_","lag":0,"age":0.10455083847045898,"walltime":0.0002460479736328125}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:content_models:wikidb-unittest_): miss, new value computed []
07:22:36 [objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:slot_roles:wikidb-unittest_","lag":0,"age":0.10513901710510254,"walltime":0.00029015541076660156}
07:22:36 [objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:slot_roles:wikidb-unittest_): miss, new value computed []
07:22:36 [EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.revision-create"}
07:22:36 [EventStreamConfig] [warning] Stream 'mediawiki.revision-create' does not match any `stream` in stream config []
07:22:36 [EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.revision-create. destination_event_service is not configured. []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-restrictions:v1:2:2): miss, new value computed []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [wfDebug] [debug] User::getBlockedStatus: checking blocked status for TestUser MediaWikiIntegrationTestCase 606748.1e7 {"private":false}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #35937 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #35937, processing time: 7.4148178100586E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #29874 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #29874, processing time: 0.0011301040649414 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_RecentChange::notifyNew #44754 []
07:22:36 [ORES] [debug] Processing edit {revid} {"revid":2}
07:22:36 [ORES] [debug] Job pushed for {revid} {"revid":2}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_RecentChange::notifyNew #44754, processing time: 0.0054500102996826 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_FlaggedRevsHooks::autoMarkPatrolled #40286 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_FlaggedRevsHooks::autoMarkPatrolled #40286, processing time: 0.0018019676208496 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started UserEditCountUpdate #41209 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended UserEditCountUpdate #41209, processing time: 0.00067806243896484 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #46643 []
07:22:36 [SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"ORESApiIntegrationTestPage"}
07:22:36 [SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"ORESApiIntegrationTestPage"}
07:22:36 [ParserCache] [debug] Saved in parser cache {"name":"pcache","key":"wikidb-unittest_:pcache:idhash:2-0!canonical","cache_time":"20220919142200","rev_id":2}
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-content-model:2): miss, new value computed []
07:22:36 [EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.page-create"}
07:22:36 [EventStreamConfig] [warning] Stream 'mediawiki.page-create' does not match any `stream` in stream config []
07:22:36 [EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.page-create. destination_event_service is not configured. []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #46643, processing time: 0.0050220489501953 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started RefreshSecondaryDataUpdate #41209 []
07:22:36 [wfDebug] [debug] BacklinkCache::queryLinks: got results from DB {"private":false}
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:linktargetstore-id:0%3AORESApiIntegrationTestPage): miss, new value computed []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended RefreshSecondaryDataUpdate #41209, processing time: 0.01329779624939 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #46926 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #46926, processing time: 9.2029571533203E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started SearchUpdate #35937 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended SearchUpdate #35937, processing time: 0.00086188316345215 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #35364 []
07:22:36 [UserOptionsManager] [debug] Loading options from database {"user_id":1}
07:22:36 [Parser] [debug] Parser::setOutputFlag: set user-signature flag on 'ORESApiIntegrationTestPage'; User signature detected []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #35364, processing time: 0.0080280303955078 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #29174 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\Notifications\Hooks::onPageSaveComplete #29174, processing time: 0.0018899440765381 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #30370 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #30370, processing time: 5.0067901611328E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #35486 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #35486, processing time: 0.00017404556274414 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started SiteStatsUpdate #43361 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended SiteStatsUpdate #43361, processing time: 0.0004270076751709 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_EchoNotificationMapper::insert #52425 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_EchoNotificationMapper::insert #52425, processing time: 0.001168966293335 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_EchoNotificationMapper::insert #46429 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_EchoNotificationMapper::insert #46429, processing time: 0.0010249614715576 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #32900 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #32900, processing time: 5.2928924560547E-5 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started CdnCacheUpdate #41559 []
07:22:36 [squid] [info] CdnCacheUpdate::purge: http://127.0.0.1:9413/index.php/ORESApiIntegrationTestPage http://127.0.0.1:9413/index.php?title=ORESApiIntegrationTestPage&action=history http://127.0.0.1:9413/index.php/Talk:ORESApiIntegrationTestPage http://127.0.0.1:9413/index.php?title=Talk:ORESApiIntegrationTestPage&action=history {"private":false}
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended CdnCacheUpdate #41559, processing time: 0.0001530647277832 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Storage\PageUpdater->saveRevision #33616 []
07:22:36 [DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Storage\PageUpdater->saveRevision #33616, processing time: 0.00014901161193848 []
07:22:36 [wfDebug] [debug] ApiMain::setCacheMode: setting cache mode private {"private":false}
07:22:36 ===
07:22:36
07:22:36 3) ORES\Tests\ScoreFetcherTest::testGetScores with data set #0 (array(array(array(array(false, array(0.32, 0.68))))), 123, 'damaging', true)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 4) ORES\Tests\ScoreFetcherTest::testGetScores with data set #1 (array(array(array(array(false, array(0.32, 0.68))), array(array(false, array(0.32, 0.68))))), 123, 'damaging|goodfaith', true)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 5) ORES\Tests\ScoreFetcherTest::testGetScores with data set #2 (array(array(array(array(false, array(0.32, 0.68))))), 123, 'damaging', false)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 6) ORES\Tests\ScoreFetcherTest::testGetScores with data set #3 (array(array(array(array(false, array(0.32, 0.68))), array(array(false, array(0.32, 0.68))))), 123, 'damaging|goodfaith', false)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 7) ORES\Tests\ScoreFetcherTest::testGetScores with data set #4 (array(array(array(array(false, array(0.32, 0.68))))), 123, null, true)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 8) ORES\Tests\ScoreFetcherTest::testGetScores with data set #5 (array(array(array(array(false, array(0.32, 0.68))))), 123, null, false)
07:22:36 Failed asserting that two arrays are equal.
07:22:36 --- Expected
07:22:36 +++ Actual
07:22:36 @@ @@
07:22:36 'prediction' => false
07:22:36 'probability' => Array (
07:22:36 'true' => 0.32
07:22:36 - 'false' => 0.68
07:22:36 + 'false' => 0.6799999999999999
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36 )
07:22:36
07:22:36 /workspace/src/extensions/ORES/tests/phpunit/includes/Services/ScoreFetcherTest.php:68
07:22:36 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:516
07:22:36 === Logs generated by test case
07:22:36 [objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
07:22:36 ===
07:22:36
07:22:36 FAILURES!
07:22:36 Tests: 1322, Assertions: 3182, Failures: 8, Skipped: 8.
07:22:36
07:22:36
07:22:36 You should really speed up these slow tests (>50ms)...
07:22:36 1. 762ms to run ParserIntegrationTest::testParse with data set "1000References.txt: Reference numbers exceeding 1000 do not have thousands separators"
07:22:36 2. 694ms to run ApiPageTriageListTest::testFilterType
07:22:36 3. 681ms to run ApiPageTriageListTest::testQueryOresCopyvio
07:22:36 4. 651ms to run MediaWiki\\Extension\\PageTriage\\Test\\MaintenancePopulateDraftQueueTest::testPreExistingPagesWithCategoriesAreGivenCorrectTags
07:22:36 5. 648ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #2
07:22:36 6. 643ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #3
07:22:36 7. 634ms to run MediaWiki\\Extension\\PageTriage\\Test\\ArticleMetadataTest::testValidatePageIds
07:22:36 8. 582ms to run MWEchoThankYouEditTest::testTenthEdit
07:22:36 9. 521ms to run ParserIntegrationTest::testParse with data set "1000References.txt: Reference reuse numbers exceeding 1000 do not have thousands separators"
07:22:36 10. 466ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #7
07:22:36 11. 448ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #1
07:22:36 12. 426ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #0
07:22:36 13. 420ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #5
07:22:36 14. 409ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #6
07:22:36 15. 401ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #9
07:22:36 16. 394ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #4
07:22:36 17. 385ms to run MediaWiki\\Extension\\PageTriage\\Test\\ArticleMetadataTest::testValidCovers
07:22:36 18. 384ms to run ApiPageTriageListTest::testUndelete
07:22:36 19. 381ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #5
07:22:36 20. 379ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #3
07:22:36 21. 374ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #1
07:22:36 22. 363ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #2
07:22:36 23. 362ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #10
07:22:36 24. 356ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #6
07:22:36 25. 355ms to run ApiPageTriageListTest::testTalkpageFeedbackCount
07:22:36 26. 343ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #4
07:22:36 27. 340ms to run MediaWiki\\Extension\\PageTriage\\Test\\ApiPageTriageTagCopyvioTest::testCopyvioInsertLog
07:22:36 28. 329ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #8
07:22:36 29. 319ms to run MediaWiki\\Extension\\PageTriage\\Test\\ArticleMetadataTest::testDeleteMetadata
07:22:36 30. 318ms to run EchoDiscussionParserTest::testGenerateEventsForRevision with data set #7
07:22:36 31. 314ms to run EchoDiscussionParserTest::testGenerateEventsForRevision_mentionStatus with data set #0
07:22:36 32. 314ms to run LazyVariableComputerDBTest::testRecentContributors
07:22:36 33. 309ms to run ApiPageTriageListTest::testUnsubmittedDrafts
07:22:36 34. 298ms to run MediaWiki\\Extension\\PageTriage\\Test\\ArticleMetadataTest::testGetMetadata
07:22:36 35. 270ms to run DatabaseIntegrationTest::testAutomaticSqlGeneration with data set #0
07:22:36 36. 259ms to run ApiPageTriageListTest::testSubmissionSorting
07:22:36 37. 256ms to run AbuseFilterConsequencesTest::testFilterConsequences with data set "No consequences"
07:22:36 38. 249ms to run ApiPageTriageListTest::testArticlesFromRedirects
07:22:36 39. 248ms to run ApiPageTriageListTest::testAutopatrolledCreation
07:22:36 40. 244ms to run ApiPageTriageListTest::testAfcTags
07:22:36 41. 242ms to run MediaWiki\\Extension\\VisualEditor\\Tests\\DirectParsoidClientTest::testGetPageHtml with data set "German language code"
07:22:36 42. 240ms to run DatabaseIntegrationTest::testAutomaticSqlGeneration with data set #1
07:22:36 43. 239ms to run AbuseFilterConsequencesTest::testStashedEdit with data set #10
07:22:36 44. 229ms to run AbuseFilterConsequencesTest::testThrottle with data set "Basic test for throttling "move""
07:22:36 45. 225ms to run ParserIntegrationTest::testParse with data set "parserTests.txt: Enclose none (inline code)"
07:22:36 46. 225ms to run EchoTalkPageFunctionalTest::testAddCommentsToTalkPage
07:22:36 47. 223ms to run ParserIntegrationTest::testParse with data set "parserTests.txt: tabs plus tidy (T32930, T59826)"
07:22:36 48. 222ms to run AbuseFilterConsequencesTest::testFilterConsequences with data set "Check that all tags are applied"
07:22:36 49. 220ms to run ParserIntegrationTest::testParse with data set "parserTests.txt: Inline attribute (inline code)"
07:22:36 50. 219ms to run ORES\\Tests\\Api\\ApiIntegrationTest::testListRecentChanges_getOresScores
07:22:36 ...and there are 170 more above your threshold hidden from view
07:22:36 Script php tests/phpunit/phpunit.php handling the phpunit event returned with error code 1
07:22:36 Script @phpunit -c tests/phpunit/suite.xml was called via phpunit:entrypoint
07:22:36 INFO:quibble.commands:<<< Finish: PHPUnit extensions suite (with database), in 90.900 s
07:22:36 INFO:backend.ChromeWebDriver:Terminating ChromeWebDriver
07:22:36 INFO:backend.Xvfb:Terminating Xvfb
07:22:36 INFO:backend.MySQL:Terminating MySQL
07:22:36 Traceback (most recent call last):
07:22:38 File "/usr/local/bin/quibble", line 10, in <module>
07:22:38 sys.exit(main())
07:22:38 File "/usr/local/lib/python3.7/dist-packages/quibble/cmd.py", line 783, in main
07:22:38 cmd.execute(plan, dry_run=args.dry_run)
07:22:38 File "/usr/local/lib/python3.7/dist-packages/quibble/cmd.py", line 512, in execute
07:22:38 quibble.commands.execute_command(command)
07:22:38 File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 26, in execute_command
07:22:38 command.execute()
07:22:38 File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 812, in execute
07:22:38 self._run_phpunit(group=['Database'], exclude_group=['Standalone'])
07:22:38 File "/usr/local/lib/python3.7/dist-packages/quibble/commands.py", line 737, in _run_phpunit
07:22:38 subprocess.check_call(cmd, cwd=self.mw_install_path, env=phpunit_env)
07:22:38 File "/usr/lib/python3.7/subprocess.py", line 347, in check_call
07:22:38 raise CalledProcessError(retcode, cmd)
07:22:38 subprocess.CalledProcessError: Command '['composer', 'run', '--timeout=0', 'phpunit:entrypoint', '--', '--testsuite', 'extensions', '--group', 'Database', '--exclude-group', 'Broken,ParserFuzz,Stub,Standalone']' returned non-zero exit status 1.
07:22:38 Build step 'Execute shell' marked build as failure
07:22:39 [PostBuildScript] - [INFO] Executing post build scripts.
07:22:39 [quibble-vendor-mysql-php74-noselenium-docker] $ /bin/bash /tmp/jenkins1821686838317138039.sh
07:22:39 + set -o pipefail
07:22:39 ++ pwd
07:22:39 + exec docker run --entrypoint=/bin/rm --volume /srv/jenkins/workspace/quibble-vendor-mysql-php74-noselenium-docker/log:/log --security-opt seccomp=unconfined --init --rm --label jenkins.job=quibble-vendor-mysql-php74-noselenium-docker --label jenkins.build=56708 --env-file /dev/fd/63 docker-registry.wikimedia.org/buster:latest -fR /log/rawSeleniumVideoGrabs
07:22:39 ++ /usr/bin/env
07:22:39 ++ egrep -v '^(HOME|SHELL|PATH|LOGNAME|MAIL)='
07:22:39 [PostBuildScript] - [INFO] Executing post build scripts.
07:22:40 [quibble-vendor-mysql-php74-noselenium-docker] $ /bin/bash -xe /tmp/jenkins1723124121888539943.sh
07:22:40 + find log/ -name 'mw-debug-*.log' -exec gzip '{}' +