Page MenuHomePhabricator

quibble-vendor-mysql-php72-noselenium-docker fails for a noop PageTriage patch
Closed, ResolvedPublic

Description

Originally found when testing this patch, @Reedy also ran a no-change patch which failed for the same reason whilst running PHPUnit extensions suite (with database):

02:25:28 INFO:quibble.commands:>>> Start: PHPUnit extensions suite (with database)
02:25:28 INFO:quibble.commands:PHPUnit extensions suite (with database)
02:25:28 INFO:quibble.commands:composer run --timeout=0 phpunit:entrypoint -- --testsuite extensions --group Database --exclude-group Broken,ParserFuzz,Stub,Standalone
02:25:28 > php tests/phpunit/phpunit.php '--testsuite' 'extensions' '--group' 'Database' '--exclude-group' 'Broken,ParserFuzz,Stub,Standalone'
02:25:28 Using PHP 7.2.34-18+0~20210223.60+debian10~1.gbpb21322+wmf5
02:25:31 PHPUnit 8.5.23 by Sebastian Bergmann and contributors.
02:25:31 
[ snip ]
02:26:31 There were 16 errors:
02:26:31
02:26:31 1) AbuseFilterConsequencesTest::testFilterConsequences with data set "Basic test for "move" action" (array(2), array('move', 'Test page', 'Another test page'), array(array(2), array(2)))
02:26:31 Undefined offset: 2
/workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php:2197
/workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php:1689
/workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php:1518
/workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php:2212
/workspace/src/extensions/PageTriage/includes/ArticleMetadata.php:198
/workspace/src/extensions/PageTriage/includes/PageTriage.php:159
/workspace/src/extensions/PageTriage/includes/PageTriage.php:57
/workspace/src/extensions/PageTriage/includes/Hooks.php:278
/workspace/src/extensions/PageTriage/includes/Hooks.php:172
/workspace/src/includes/HookContainer/HookContainer.php:338
/workspace/src/includes/HookContainer/HookContainer.php:137
/workspace/src/includes/HookContainer/HookRunner.php:2807
/workspace/src/includes/Storage/PageUpdater.php:1588
/workspace/src/includes/libs/rdbms/database/Database.php:4434
/workspace/src/includes/libs/rdbms/database/DBConnRef.php:69
/workspace/src/includes/libs/rdbms/database/DBConnRef.php:645
/workspace/src/includes/deferred/AtomicSectionUpdate.php:39
/workspace/src/includes/deferred/DeferredUpdates.php:536
/workspace/src/includes/deferred/DeferredUpdates.php:419
/workspace/src/includes/deferred/DeferredUpdates.php:229
/workspace/src/includes/deferred/DeferredUpdatesScope.php:267
/workspace/src/includes/deferred/DeferredUpdatesScope.php:196
/workspace/src/includes/deferred/DeferredUpdates.php:250
/workspace/src/includes/deferred/DeferredUpdates.php:301
/workspace/src/includes/deferred/DeferredUpdates.php:136
/workspace/src/includes/Storage/PageUpdater.php:1525
/workspace/src/includes/Storage/PageUpdater.php:911
/workspace/src/includes/page/WikiPage.php:2002
/workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:275
/workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:555
/workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:783
/workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php:457
=== Logs generated by test case
[objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
[localisation] [debug] LocalisationCache using store LCStoreNull []
[UserOptionsManager] [debug] Loading options from database {"user_id":2}
[GlobalTitleFail] [info] RequestContext::getTitle called with no title set. {"exception":{}}
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_EchoHooks::onUserSaveSettings #32419 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_EchoHooks::onUserSaveSettings #32419, processing time: 0.00044107437133789 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\User\UserGroupManager->addUserToGroup #32415 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\User\UserGroupManager->addUserToGroup #32415, processing time: 0.00064301490783691 []
[localisation] [debug] LocalisationCache using store LCStoreNull []
[objectcache] [debug] MainWANObjectCache using store {class} {"class":"EmptyBagOStuff"}
[ContentHandler] [info] Registered handler for wikitext: WikitextContentHandler []
[objectcache] [debug] MainObjectStash using store {class} {"class":"HashBagOStuff"}
[ParserCache] [debug] Creating ParserCache instance for pcache []
[MessageCache] [debug] MessageCache using store {class} {"class":"HashBagOStuff"}
[wfDebug] [debug] User::getBlockedStatus: checking blocked status for UTSysop {"private":false}
[UserOptionsManager] [debug] Loading options from database {"user_id":1}
[wfDebug] [debug] ParserFactory: using default preprocessor {"private":false}
[localisation] [debug] LocalisationCache::isExpired(en): cache missing, need to make one []
[objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:content_models:wikidb-unittest_","lag":0,"age":0.2500460147857666,"walltime":0.00030398368835449219}
[objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:content_models:wikidb-unittest_): miss, new value computed []
[objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:NameTableSqlStore:slot_roles:wikidb-unittest_","lag":0,"age":0.2505791187286377,"walltime":0.00027418136596679688}
[objectcache] [debug] fetchOrRegenerate(global:NameTableSqlStore:slot_roles:wikidb-unittest_): miss, new value computed []
[EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.revision-create"}
[EventStreamConfig] [warning] Stream 'mediawiki.revision-create' does not match any `stream` in stream config []
[EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.revision-create. destination_event_service is not configured. []
[objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-restrictions:v1:2:2): miss, new value computed []
[objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-restrictions:v1:2:2): miss, new value computed []
[ParserCache] [debug] Creating RevisionOutputCache instance for rcache []
[objectcache] [warning] Rejected set() for {cachekey} due to pending writes. {"cachekey":"global:revision-row-1.29:wikidb-unittest_:2:2","lag":0,"age":0.25769615173339844,"walltime":0.00079298019409179688}
[objectcache] [debug] fetchOrRegenerate(global:revision-row-1.29:wikidb-unittest_:2:2): miss, new value computed []
[objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:page-content-model:2): miss, new value computed []
[objectcache] [debug] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit []
[ParserCache] [debug] ParserOutput metadata cache miss {"name":"pcache"}
[objectcache] [debug] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit []
[objectcache] [debug] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit []
[ParserCache] [debug] ParserOutput metadata cache miss {"name":"pcache"}
[ParserCache] [debug] Saved in parser cache {"name":"pcache","key":"wikidb-unittest_:pcache:idhash:2-0!canonical","cache_time":"20220305022533","rev_id":2}
[objectcache] [debug] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit []
[DeferredUpdates] [debug] DeferredUpdates::run: started AutoCommitUpdate_Title::invalidateCache #32134 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended AutoCommitUpdate_Title::invalidateCache #32134, processing time: 0.00043797492980957 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #32118 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #32118, processing time: 5.3167343139648E-5 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #32122 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #32122, processing time: 0.0012390613555908 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_FlaggedRevs::purgeSquid #32298 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_FlaggedRevs::purgeSquid #32298, processing time: 0.00019192695617676 []
[DeferredUpdates] [debug] DeferredUpdates::run: started UserEditCountUpdate #32088 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended UserEditCountUpdate #32088, processing time: 0.00047492980957031 []
[DeferredUpdates] [debug] DeferredUpdates::run: started CdnCacheUpdate #32064 []
[squid] [info] CdnCacheUpdate::purge: http://127.0.0.1:9412/index.php/Test_page http://127.0.0.1:9412/index.php?title=Test_page&action=history {"private":false}
[DeferredUpdates] [debug] DeferredUpdates::run: ended CdnCacheUpdate #32064, processing time: 0.00013089179992676 []
[DeferredUpdates] [debug] DeferredUpdates::run: started AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #32032 []
[SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"Test page"}
[SaveParse] [debug] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for '{title}' {"title":"Test page"}
[ParserCache] [debug] Saved in parser cache {"name":"pcache","key":"wikidb-unittest_:pcache:idhash:2-0!canonical","cache_time":"20220305022533","rev_id":2}
[objectcache] [debug] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit []
[EventStreamConfig] [debug] Selecting stream configs for target streams: {streams} {"streams":"mediawiki.page-create"}
[EventStreamConfig] [warning] Stream 'mediawiki.page-create' does not match any `stream` in stream config []
[EventBus] [debug] Using EventServiceDefault eventbus for stream mediawiki.page-create. destination_event_service is not configured. []
[objectcache] [debug] fetchOrRegenerate(wikidb-unittest_:pagetriage-valid-tags): miss, new value computed []
[exception] [error] [{reqId}] {exception_url}   PHPUnit\Framework\Error\Notice: Undefined offset: 2 {"exception":{},"exception_url":"[no req]","reqId":"f04b831ec635d2308c616f81","caught_by":"other"}
..
[DeferredUpdates] [error] Deferred update '{deferred_type}' failed to run. {"deferred_type":"AtomicSectionUpdate_MediaWiki\\Storage\\PageUpdater::getAtomicSectionUpdate","exception":{}}
[DeferredUpdates] [debug] DeferredUpdates::run: ended AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #32032, processing time: 0.0078108310699463 []
[DeferredUpdates] [debug] DeferredUpdates::run: started RefreshSecondaryDataUpdate #32063 []
[wfDebug] [debug] BacklinkCache::queryLinks: got results from DB {"private":false}
[DeferredUpdates] [debug] DeferredUpdates::run: ended RefreshSecondaryDataUpdate #32063, processing time: 0.01281213760376 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #32088 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Storage\DerivedPageDataUpdater->doUpdates #32088, processing time: 8.0108642578125E-5 []
[DeferredUpdates] [debug] DeferredUpdates::run: started SearchUpdate #32135 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended SearchUpdate #32135, processing time: 0.00079607963562012 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_EchoHooks::onPageSaveComplete #32105 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_EchoHooks::onPageSaveComplete #32105, processing time: 0.0015828609466553 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #32136 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #32136, processing time: 4.7206878662109E-5 []
[DeferredUpdates] [debug] DeferredUpdates::run: started AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #32015 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended AutoCommitUpdate_MediaWiki\Deferred\LinksUpdate\LinksUpdate::doUpdate #32015, processing time: 0.00014376640319824 []
[DeferredUpdates] [debug] DeferredUpdates::run: started SiteStatsUpdate #32052 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended SiteStatsUpdate #32052, processing time: 0.00045299530029297 []
[DeferredUpdates] [debug] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #32140 []
[DeferredUpdates] [debug] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\PageTriage\Hooks::onLinksUpdateComplete #32140, processing time: 5.5074691772461E-5 []
[DeferredUpdates] [debug] DeferredUpdates::run: started CdnCacheUpdate #32089 []
[squid] [info] CdnCacheUpdate::purge: http://127.0.0.1:9412/index.php/Test_page http://127.0.0.1:9412/index.php?title=Test_page&action=history http://127.0.0.1:9412/index.php/Talk:Test_page http://127.0.0.1:9412/index.php?title=Talk:Test_page&action=history {"private":false}
[DeferredUpdates] [debug] DeferredUpdates::run: ended CdnCacheUpdate #32089, processing time: 0.00012493133544922 []

I've kept the noop build (as I don't know how often they're removed)

Event Timeline

Daimona added a subscriber: Daimona.

I don't see how AF could be at fault here, the test simply calls MediaWikiIntegrationTestCase::getExistingTestPage and that's it. I would say this is an issue with PageTriage itself; whether it's an actual coding mistake (like a missing LBYL check) or something wrong with the test configuration (e.g. the global is not set, or it's using the wrong cache type), I don't know.

However, it's not clear to me why the cache version is a global variable. Such things are usually class constants, because they should only be updated by the developers when changing the code. Making it a constant would also avoid any issue related to the value possibly being unset at some early point during the test. Also, the cache version is documented as an integer in WANObjectCache, so I'm not sure if it's safe to pass a float. It probably is, but I wouldn't make that assumption in a codebase that I maintain.

RhinosF1 triaged this task as Unbreak Now! priority.Mar 5 2022, 1:15 PM
RhinosF1 added a subscriber: RhinosF1.

Deployed build failure = UBN

I don't see how AF could be at fault here, the test simply calls MediaWikiIntegrationTestCase::getExistingTestPage and that's it. I would say this is an issue with PageTriage itself; whether it's an actual coding mistake (like a missing LBYL check) or something wrong with the test configuration (e.g. the global is not set, or it's using the wrong cache type), I don't know.

Indeed an AF no-op patch by itself doesn't fail - https://gerrit.wikimedia.org/r/c/mediawiki/extensions/AbuseFilter/+/768148

Change 768148 had a related patch set uploaded (by Huji; author: Reedy):

[mediawiki/extensions/AbuseFilter@master] [DNM] test no-op patch to investigate T303092

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

Change 768148 abandoned by Huji:

[mediawiki/extensions/AbuseFilter@master] [DNM] test no-op patch to investigate T303092

Reason:

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

Change 768711 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/extensions/PageTriage@master] Change wgPageTriageCacheVersion to integer class constant

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

I can't reproduce the failure locally, of course.

Making it a constant would also avoid any issue related to the value possibly being unset at some early point during the test. Also, the cache version is documented as an integer in WANObjectCache, so I'm not sure if it's safe to pass a float. It probably is, but I wouldn't make that assumption in a codebase that I maintain.

Let's see if https://gerrit.wikimedia.org/r/768711 helps

Tagging @aaron and @Krinkle in case they have ideas about the WANObjectCache failure.

Change 768738 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] objectcache: Clean up getMultiWithUnionSetCallback() test cases

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

I haven't found a bug or solved anything, but I have confirmed that the getMultiWithUnionSetCallback() and makeMultiKeys() method are well-tested and seem to (generally) be working as intended and without any run-time errors, including in combination with the version feature as PageTriage does.

Change 771336 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/core@master] [DNM] Debug logging for WANObjectCache

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

Change 771336 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/core@master] [DNM] Debug logging for WANObjectCache

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

I added some debug logging. Here's are the logs with 50 lines of context on either side of the WANObjectCache error:

[DBQuery] ChangeTags::getTagsWithData [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  ct_tag_id,ct_params  FROM `unittest_change_tag`    WHERE ct_rev_id = 2 AND ct_log_id = '4'
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] CommentStore::createComment [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  comment_id  FROM `unittest_comment`    WHERE comment_hash = 1590154186 AND comment_text = 'UTPageSummary' AND comment_data IS NULL  LIMIT 1
[DBQuery] ManualLogEntry::insert [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: INSERT INTO `unittest_logging` (log_type,log_action,log_timestamp,log_actor,log_namespace,log_title,log_page,log_params,log_comment_id) VALUES ('create','create','20171231060000',1,0,'AbuseFilter_testing_page',2,'a:1:{s:17:\"associated_rev_id\";i:2;}',1)
[DBQuery] ManualLogEntry::insert [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: INSERT IGNORE INTO `unittest_log_search` (ls_field,ls_value,ls_log_id) VALUES ('associated_rev_id',2,26)
[DBQuery] endAtomic: leaving level 0 (MediaWiki\Storage\PageUpdater::doCreate)
[DBQuery] MediaWiki\Storage\PageUpdater::doCreate [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: COMMIT
[DeferredUpdates] DeferredUpdates::run: started MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #38224
[DeferredUpdates] DeferredUpdates::run: ended MWCallableUpdate_MediaWiki\Extension\EventBus\EventBusHooks::sendRevisionCreateEvent #38224, processing time: 0.00011610984802246
[DeferredUpdates] DeferredUpdates::run: started MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #38218
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (/workspace/src/extensions/WikimediaEvents/includes/WikimediaEventsHooks.php:235) [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: BEGIN
[DBQuery] /workspace/src/extensions/WikimediaEvents/includes/WikimediaEventsHooks.php:235 [0.001s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  COUNT(*) AS `rowcount`  FROM (SELECT  1  FROM `unittest_revision` JOIN `unittest_page` ON ((rev_page = page_id)) JOIN `unittest_revision_actor_temp` `temp_rev_user` ON ((temp_rev_user.revactor_rev = rev_id))   WHERE (temp_rev_user.revactor_actor = 1) AND (revactor_timestamp >= '20220228000000') AND page_namespace = 0  LIMIT 6  ) `tmp_count`
[DBQuery] WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: COMMIT
[DeferredUpdates] DeferredUpdates::run: ended MWCallableUpdate_WikimediaEvents\WikimediaEventsHooks::onRevisionRecordInserted #38218, processing time: 0.0011951923370361
[DeferredUpdates] DeferredUpdates::run: started UserEditCountUpdate #36605
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] UserEditCountUpdate::doUpdate [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: UPDATE  `unittest_user` SET user_editcount=user_editcount+1 WHERE user_id = 1 AND (user_editcount IS NOT NULL)
[DeferredUpdates] DeferredUpdates::run: ended UserEditCountUpdate #36605, processing time: 0.00049304962158203
[DeferredUpdates] DeferredUpdates::run: started AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #38238
[DBQuery] MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: BEGIN
[DBQuery] startAtomic: entering level 0 (MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate)
[SaveParse] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for 'AbuseFilter testing page'
[SaveParse] MediaWiki\Revision\RenderedRevision::outputVariesOnRevisionMetaData: reusing prepared output for 'AbuseFilter testing page'
[ParserCache] Saved in parser cache
[objectcache] getWithSetCallback(wikidb-unittest_:page-content-model:2): process cache hit
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Permissions\RestrictionStore::deleteCreateProtection [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: DELETE FROM `unittest_protected_titles` WHERE pt_namespace = 0 AND pt_title = 'AbuseFilter_testing_page'
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\User\UserEditTracker::getUserEditCount [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  user_editcount  FROM `unittest_user`    WHERE user_id = 1  LIMIT 1
[EventStreamConfig] Selecting stream configs for target streams: mediawiki.page-create
[EventStreamConfig] Stream 'mediawiki.page-create' does not match any `stream` in stream config
[EventBus] Using EventServiceDefault eventbus for stream mediawiki.page-create. destination_event_service is not configured.
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Extension\PageTriage\PageTriage::retrieve [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  ptrp_reviewed,ptrp_created,ptrp_deleted,ptrp_tags_updated,ptrp_reviewed_updated,ptrp_last_reviewed_by  FROM `unittest_pagetriage_page`    WHERE ptrp_page_id = 2  LIMIT 1
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] startAtomic: entering level 1 (MediaWiki\Extension\PageTriage\PageTriage::setTriageStatus)
[DBQuery] MediaWiki\Extension\PageTriage\PageTriage::setTriageStatus [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: UPDATE  `unittest_pagetriage_page` SET ptrp_reviewed = 3,ptrp_reviewed_updated = '20171231060000',ptrp_last_reviewed_by = 1 WHERE ptrp_page_id = 2 AND (ptrp_reviewed != 3)
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Extension\PageTriage\PageTriage::setTriageStatus [0.001s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  rc_id,rc_timestamp,rc_namespace,rc_title,rc_minor,rc_bot,rc_new,rc_cur_id,rc_this_oldid,rc_last_oldid,rc_type,rc_source,rc_patrolled,rc_ip,rc_old_len,rc_new_len,rc_deleted,rc_logid,rc_log_type,rc_log_action,rc_params,rc_actor,recentchanges_actor.actor_user AS `rc_user`,recentchanges_actor.actor_name AS `rc_user_text`,comment_rc_comment.comment_text AS `rc_comment_text`,comment_rc_comment.comment_data AS `rc_comment_data`,comment_rc_comment.comment_id AS `rc_comment_cid`  FROM `unittest_recentchanges` JOIN `unittest_actor` `recentchanges_actor` ON ((actor_id=rc_actor)) JOIN `unittest_comment` `comment_rc_comment` ON ((comment_rc_comment.comment_id = rc_comment_id))   WHERE rc_cur_id = 2 AND rc_new = '1'  LIMIT 1
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Extension\PageTriage\PageTriage::logUserTriageAction [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: INSERT INTO `unittest_pagetriage_log` (ptrl_page_id,ptrl_user_id,ptrl_reviewed,ptrl_timestamp) VALUES (2,1,3,'20171231060000')
[DBQuery] endAtomic: leaving level 1 (MediaWiki\Extension\PageTriage\PageTriage::setTriageStatus)
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Extension\PageTriage\ArticleMetadata::getMetadataForArticles [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  ptrpt_page_id,ptrt_tag_name,ptrpt_value,ptrp_reviewed,ptrp_created,page_title,page_namespace,page_is_redirect,ptrp_last_reviewed_by,ptrp_reviewed_updated,user_name AS `reviewer`  FROM `unittest_pagetriage_page_tags`,`unittest_pagetriage_tags`,`unittest_page`,`unittest_pagetriage_page` LEFT JOIN `unittest_user` ON ((user_id = ptrp_last_reviewed_by))   WHERE ptrpt_page_id = 2 AND (ptrpt_tag_id = ptrt_tag_id) AND (ptrpt_page_id = ptrp_page_id) AND (page_id = ptrp_page_id)
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0
[DBQuery] MediaWiki\Extension\PageTriage\ArticleMetadata::getValidTags [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: SELECT  ptrt_tag_id,ptrt_tag_name  FROM `unittest_pagetriage_tags`
[objectcache] fetchOrRegenerate(wikidb-unittest_:pagetriage-valid-tags): miss, new value computed
[objectcache] WANObjectCache::getMultiWithUnionSetCallback failed due to 2 not being set in result [] for keyedIds {"wikidb-unittest_:pagetriage-article-metadata:2":2}
[DBQuery] cancelAtomic: canceling level 0 (MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate)
[DeferredUpdates] Deferred update 'AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate' failed to run.
#0 /workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php(2208): PHPUnit\Util\ErrorHandler->__invoke(integer, string, string, integer, array)
#1 /workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php(1689): WANObjectCache::{closure}(boolean, integer, array, NULL, array)
#2 /workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php(1518): WANObjectCache->fetchOrRegenerate(string, integer, Closure, array, array)
#3 /workspace/src/includes/libs/objectcache/wancache/WANObjectCache.php(2223): WANObjectCache->getWithSetCallback(string, integer, Closure, array, array)
#4 /workspace/src/extensions/PageTriage/includes/ArticleMetadata.php(196): WANObjectCache->getMultiWithUnionSetCallback(ArrayIterator, integer, Closure, array)
#5 /workspace/src/extensions/PageTriage/includes/PageTriage.php(161): MediaWiki\Extension\PageTriage\ArticleMetadata->getMetadata()
#6 /workspace/src/extensions/PageTriage/includes/PageTriage.php(59): MediaWiki\Extension\PageTriage\PageTriage->setTriageStatus(integer, User, boolean)
#7 /workspace/src/extensions/PageTriage/includes/Hooks.php(278): MediaWiki\Extension\PageTriage\PageTriage->addToPageTriageQueue(integer, User)
#8 /workspace/src/extensions/PageTriage/includes/Hooks.php(172): MediaWiki\Extension\PageTriage\Hooks::addToPageTriageQueue(integer, Title, User)
#9 /workspace/src/includes/HookContainer/HookContainer.php(338): MediaWiki\Extension\PageTriage\Hooks::onPageSaveComplete(WikiPage, User, string, integer, MediaWiki\Revision\RevisionStoreRecord, MediaWiki\Storage\EditResult)
#10 /workspace/src/includes/HookContainer/HookContainer.php(137): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#11 /workspace/src/includes/HookContainer/HookRunner.php(2807): MediaWiki\HookContainer\HookContainer->run(string, array)
#12 /workspace/src/includes/Storage/PageUpdater.php(1588): MediaWiki\HookContainer\HookRunner->onPageSaveComplete(WikiPage, User, string, integer, MediaWiki\Revision\RevisionStoreRecord, MediaWiki\Storage\EditResult)
#13 /workspace/src/includes/libs/rdbms/database/Database.php(4576): MediaWiki\Storage\PageUpdater->MediaWiki\Storage\{closure}(Wikimedia\Rdbms\DatabaseMysqli, string)
#14 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->doAtomicSection(string, Closure)
#15 /workspace/src/includes/libs/rdbms/database/DBConnRef.php(605): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#16 /workspace/src/includes/deferred/AtomicSectionUpdate.php(39): Wikimedia\Rdbms\DBConnRef->doAtomicSection(string, Closure)
#17 /workspace/src/includes/deferred/DeferredUpdates.php(536): AtomicSectionUpdate->doUpdate()
#18 /workspace/src/includes/deferred/DeferredUpdates.php(419): DeferredUpdates::attemptUpdate(AtomicSectionUpdate, Wikimedia\Rdbms\LBFactorySimple)
#19 /workspace/src/includes/deferred/DeferredUpdates.php(229): DeferredUpdates::run(AtomicSectionUpdate, Wikimedia\Rdbms\LBFactorySimple, class@anonymous/workspace/src/includes/debug/logger/LogCapturingSpi.php0x7f6f8cff470f, BufferingStatsdDataFactory, MediaWiki\JobQueue\JobQueueGroupFactory, string)
#20 /workspace/src/includes/deferred/DeferredUpdatesScope.php(267): DeferredUpdates::{closure}(AtomicSectionUpdate, integer)
#21 /workspace/src/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#22 /workspace/src/includes/deferred/DeferredUpdates.php(250): DeferredUpdatesScope->processUpdates(integer, Closure)
#23 /workspace/src/includes/deferred/DeferredUpdates.php(301): DeferredUpdates::doUpdates(string, integer)
#24 /workspace/src/includes/deferred/DeferredUpdates.php(136): DeferredUpdates::tryOpportunisticExecute(string)
#25 /workspace/src/includes/Storage/PageUpdater.php(1525): DeferredUpdates::addUpdate(AtomicSectionUpdate, integer)
#26 /workspace/src/includes/Storage/PageUpdater.php(911): MediaWiki\Storage\PageUpdater->doCreate(CommentStoreComment)
#27 /workspace/src/includes/page/WikiPage.php(1994): MediaWiki\Storage\PageUpdater->saveRevision(CommentStoreComment, integer)
#28 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php(275): WikiPage->doUserEditContent(WikitextContent, User, CommentStoreComment, integer)
#29 /workspace/src/extensions/AbuseFilter/tests/phpunit/RCVariableGeneratorTest.php(54): MediaWikiIntegrationTestCase->getExistingTestPage(Title)
#30 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1490): RCVariableGeneratorTest->testGetVarsFromRCRow(string, string)
#31 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(1110): PHPUnit\Framework\TestCase->runTest()
#32 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestResult.php(703): PHPUnit\Framework\TestCase->runBare()
#33 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestCase.php(838): PHPUnit\Framework\TestResult->run(RCVariableGeneratorTest)
#34 /workspace/src/tests/phpunit/MediaWikiIntegrationTestCase.php(457): PHPUnit\Framework\TestCase->run(PHPUnit\Framework\TestResult)
#35 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(626): MediaWikiIntegrationTestCase->run(PHPUnit\Framework\TestResult)
#36 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(626): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#37 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(626): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#38 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(626): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#39 /workspace/src/vendor/phpunit/phpunit/src/Framework/TestSuite.php(626): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#40 /workspace/src/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(659): PHPUnit\Framework\TestSuite->run(PHPUnit\Framework\TestResult)
#41 /workspace/src/vendor/phpunit/phpunit/src/TextUI/Command.php(235): PHPUnit\TextUI\TestRunner->doRun(PHPUnit\Framework\TestSuite, array, array, boolean)
#42 /workspace/src/tests/phpunit/phpunit.php(140): PHPUnit\TextUI\Command->run(array, boolean)
#43 /workspace/src/tests/phpunit/phpunit.php(201): PHPUnitMaintClass->execute()
#44 {main}
[DBQuery] DeferredUpdates::run [0s] localhost:/workspace/db/quibble-mysql-zwksj1m6/socket: ROLLBACK
[DBConnection] DeferredUpdates::run: acknowledged server-side transaction loss on localhost:/workspace/db/quibble-mysql-zwksj1m6/socket
[DeferredUpdates] DeferredUpdates::run: ended AtomicSectionUpdate_MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate #38238, processing time: 0.006219148635864

The method, getMultiWithUnionSetCallback(), seems to expect explicit "false" values for missing items...I'll update the docs/tests.

Change 771457 had a related patch set uploaded (by Aaron Schulz; author: Aaron Schulz):

[mediawiki/core@master] objectcache: clarify usage of getMultiWithUnionSetCallback()

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

Change 771611 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/extensions/PageTriage@master] [WIP] ArticleMetadata: Validate page IDs before using with cache get

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

Change 771457 merged by jenkins-bot:

[mediawiki/core@master] objectcache: clarify usage of getMultiWithUnionSetCallback()

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

Change 768738 merged by jenkins-bot:

[mediawiki/core@master] objectcache: Clean up getMultiWithUnionSetCallback() test cases

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

Change 771611 merged by jenkins-bot:

[mediawiki/extensions/PageTriage@master] ArticleMetadata: Ensure fallback value is set for each page ID

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

CI works again for PageTriage.

CI works again for PageTriage.

Woo! Did a recheck on https://gerrit.wikimedia.org/r/c/mediawiki/extensions/PageTriage/+/768185 and its finally passing, thank you all!

Change 771336 merged by jenkins-bot:

[mediawiki/core@master] objectcache: Warn when WANObjectCache callback returns incomplete result

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