Lucas_Werkmeister_WMDE added a comment.
We deployed PS2 of the debug code <https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Wikibase/+/989125/2/> on mwdebug2001, and only saw two logstash messages: - T255706 debug: onParserCacheSaveComplete with 47 usages, 79 currentUsages, 0 newUsages <https://logstash.wikimedia.org/app/dashboards#/doc/logstash-*/logstash-mediawiki-1-7.0.0-1-2024.01.09?id=ggYE7owBySCoT0gdkiK4> - T255706 debug: onParserCacheSaveComplete return early <https://logstash.wikimedia.org/app/dashboards#/doc/logstash-*/logstash-mediawiki-1-7.0.0-1-2024.01.09?id=jZME7owBW1B7XSkmkljZ> This demonstrates that the early return was indeed taken, and no job should have been enqueued – and yet it was, with the same request ID as those logstash messages (reqId `80a7e163-2dc6-4202-a5f8-ff0ac7b910ac`): {"$schema":"/mediawiki/job/1.0.0","meta":{"uri":"https://placeholder.invalid/wiki/Special:Badtitle","request_id":"80a7e163-2dc6-4202-a5f8-ff0ac7b910ac","id":"a31c55a1-a716-4286-b57a-0dcdddf583eb","dt":"2024-01-09T11:38:46Z","domain":"eo.wikipedia.org","stream":"mediawiki.job.wikibase-addUsagesForPage"},"database":"eowiki","type":"wikibase-addUsagesForPage","sha1":"8ad2a549a2258f3c839f81639c8f42eb6537b789","params":{"namespace":0,"title":"Perseo","pageId":115136,"usages":{"Q130832#C.P1559":{"entityId":"Q130832","aspect":"C","modifier":"P1559"},"Q130832#C.P21":{"entityId":"Q130832","aspect":"C","modifier":"P21"},"Q130832#C.P263":{"entityId":"Q130832","aspect":"C","modifier":"P263"},"Q130832#C.P460":{"entityId":"Q130832","aspect":"C","modifier":"P460"},"Q130832#C.P22":{"entityId":"Q130832","aspect":"C","modifier":"P22"},"Q130832#C.P25":{"entityId":"Q130832","aspect":"C","modifier":"P25"},"Q130832#C.P26":{"entityId":"Q130832","aspect":"C","modifier":"P26"},"Q130832#C.P40":{"entityId":"Q130832","aspect":"C","modifier":"P40"},"Q130832#C.P451":{"entityId":"Q130832","aspect":"C","modifier":"P451"},"Q130832#C.P935":{"entityId":"Q130832","aspect":"C","modifier":"P935"},"Q130832#C.P373":{"entityId":"Q130832","aspect":"C","modifier":"P373"},"Q130832#C.P225":{"entityId":"Q130832","aspect":"C","modifier":"P225"},"Q130832#C.P227":{"entityId":"Q130832","aspect":"C","modifier":"P227"},"Q130832#C.P244":{"entityId":"Q130832","aspect":"C","modifier":"P244"},"Q130832#C.P214":{"entityId":"Q130832","aspect":"C","modifier":"P214"},"Q130832#C.P213":{"entityId":"Q130832","aspect":"C","modifier":"P213"},"Q130832#C.P906":{"entityId":"Q130832","aspect":"C","modifier":"P906"},"Q130832#C.P269":{"entityId":"Q130832","aspect":"C","modifier":"P269"},"Q130832#C.P268":{"entityId":"Q130832","aspect":"C","modifier":"P268"},"Q130832#C.P496":{"entityId":"Q130832","aspect":"C","modifier":"P496"},"Q130832#C.P651":{"entityId":"Q130832","aspect":"C","modifier":"P651"},"Q130832#C.P245":{"entityId":"Q130832","aspect":"C","modifier":"P245"},"Q130832#C.P434":{"entityId":"Q130832","aspect":"C","modifier":"P434"},"Q130832#C.P409":{"entityId":"Q130832","aspect":"C","modifier":"P409"},"Q130832#C.P349":{"entityId":"Q130832","aspect":"C","modifier":"P349"},"Q130832#C.P1015":{"entityId":"Q130832","aspect":"C","modifier":"P1015"},"Q130832#C.P1053":{"entityId":"Q130832","aspect":"C","modifier":"P1053"},"Q130832#C.P650":{"entityId":"Q130832","aspect":"C","modifier":"P650"},"Q130832#C.P691":{"entityId":"Q130832","aspect":"C","modifier":"P691"},"Q130832#C.P396":{"entityId":"Q130832","aspect":"C","modifier":"P396"},"Q130832#C.P950":{"entityId":"Q130832","aspect":"C","modifier":"P950"}},"requestId":"80a7e163-2dc6-4202-a5f8-ff0ac7b910ac"},"mediawiki_signature":"2c7097c68efae5751591caed7b353906151683cd"} We were quite baffled by this, but eventually looked through some recent EventBus log messages (`dd` ranges found by trial and error based on the timestamps): dd if=/srv/mw-log/EventBus.log of=/dev/stdout bs=1M skip=17000 count=100 | grep 80a7e163-2dc6-4202-a5f8-ff0ac7b910ac 2024-01-09 11:38:45.788103 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream resource_change. 2024-01-09 11:38:45.923180 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream mediawiki.job.cirrusSearchLinksUpdate. 2024-01-09 11:38:45.996112 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-analytics-external for stream eventlogging_EditAttemptStep. 2024-01-09 11:38:46.018591 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-analytics-external for stream eventlogging_VisualEditorFeatureUse. 2024-01-09 11:38:46.024510 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-analytics-external for stream eventlogging_EditAttemptStep. 2024-01-09 11:38:46.046193 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mwdebug2001 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream mediawiki.job.parsoidCachePrewarm. 2024-01-09 11:38:46.107792 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mw2278 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream mediawiki.job.cirrusSearchElasticaWrite. 2024-01-09 11:38:46.777306 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mw2279 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream mediawiki.job.RecordLintJob. 2024-01-09 11:38:46.874375 [80a7e163-2dc6-4202-a5f8-ff0ac7b910ac] mw2279 eowiki 1.42.0-wmf.12 EventBus DEBUG: Using event intake service eventgate-main for stream mediawiki.job.wikibase-addUsagesForPage. We can see that the first few log messages here come from mwdebug2001, but then there are some from regular MediaWiki app servers! This would explain why we didn’t see a log message for the job being enqueued: we only deployed the logging code to mwdebug2001, after all. Our current theory is that the `parsoidCachePrewarm` job, scheduled on mwdebug2001, ran on mw2279 and caused a new parser cache write, which then created the `wikibase-addUsagesForPage` job. To test this, we would have to deploy debug logging to all of production, not just mwdebug (similar to the debug code at the end of T255706#9423170 <https://phabricator.wikimedia.org/T255706#9423170>, which we didn’t end up deploying after all). TASK DETAIL https://phabricator.wikimedia.org/T255706 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: Lucas_Werkmeister_WMDE Cc: ArthurTaylor, hoo, Lucas_Werkmeister_WMDE, ItamarWMDE, Ladsgroup, Krinkle, eprodromou, aaron, Michael, Aklapper, thcipriani, Danny_Benjafield_WMDE, Isabelladantes1983, Themindcoder, Adamm71, Jersione, Hellket777, LisafBia6531, Astuthiodit_1, 786, Biggs657, karapayneWMDE, Invadibot, maantietaja, Juan90264, Alter-paule, Beast1978, Un1tY, Akuckartz, Hook696, darthmon_wmde, Rosalie_WMDE, Kent7301, joker88john, CucyNoiD, Nandana, Gaboe420, Giuliamocci, Cpaulf30, Lahi, Gq86, Af420, Bsandipan, GoranSMilovanovic, QZanden, KimKelting, LawExplorer, Lewizho99, Maathavan, _jensen, rosalieper, Neuronton, Scott_WUaS, Verdy_p, Wikidata-bugs, aude, Jdforrester-WMF, Mbch331, Jay8g
_______________________________________________ Wikidata-bugs mailing list -- wikidata-bugs@lists.wikimedia.org To unsubscribe send an email to wikidata-bugs-le...@lists.wikimedia.org
