Reported multiple times in T388416 (description and comments). Reproduced in the test patch r1130680 with full debug logging: https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/40825/console (build kept forever).
Description
Description
Details
Details
Related Changes in Gerrit:
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Open | None | T388416 CI jobs failing with various timeouts (March 2025) | |||
| Open | Daimona | T389863 api-testing CI failure: Timeout of 5000ms exceeded in "before all" hook in "POST /campaignevents/v0/event_registration" | |||
| Resolved | Daimona | T390865 Do not fetch Tor exit nodes via HTTP in quibble |
Event Timeline
Comment Actions
I instrumented the test setup code with the following:
this.timeout( 5000 ); console.log( 'Start: ' + new Date() ); const organizerUser = await EventUtils.getOrganizerUser(); console.log( 'Got organizer: ' + new Date() ); organizerToken = await organizerUser.token(); console.log( 'Got organizer token: ' + new Date() ); const anonUser = action.getAnon(); console.log( 'Got anon: ' + new Date() ); anonToken = await anonUser.token(); console.log( 'Got anon token: ' + new Date() ); const blockedUser = await action.blockedUser(); console.log( 'Got blocked: ' + new Date() ); blockedUserToken = await blockedUser.token(); console.log( 'Got blocked token: ' + new Date() ); anonClient = new REST( 'rest.php/campaignevents/v0/event_registration' ); console.log( 'Constructed anon client: ' + new Date() ); organizerClient = clientFactory.getRESTClient( 'rest.php/campaignevents/v0/event_registration', organizerUser ); console.log( 'Constructed organizer client: ' + new Date() ); blockedUserClient = clientFactory.getRESTClient( 'rest.php/campaignevents/v0/event_registration', blockedUser ); console.log( 'Constructed blocked client: ' + new Date() ); eventPage = utils.title( 'Event:Event page ' ); await organizerUser.edit( eventPage, {} ); console.log( 'Done edit: ' + new Date() );
Which printed:
20:52:14 POST /campaignevents/v0/event_registration 20:52:14 Start: Mon Mar 24 2025 20:52:14 GMT+0000 (Coordinated Universal Time) 20:52:18 Got organizer: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Got organizer token: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Got anon: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Got anon token: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Got blocked: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Got blocked token: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Constructed anon client: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Constructed organizer client: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:18 Constructed blocked client: Mon Mar 24 2025 20:52:18 GMT+0000 (Coordinated Universal Time) 20:52:19 1) "before all" hook in "POST /campaignevents/v0/event_registration"
So we see that ~4 seconds are spent in the initial EventUtils.getOrganizerUser() call. Then, everything else runs within ~1 second, but we've already used up roughly 4/5 of our budgeted time, hence the timeout. All that the getOrganizerUser call does is call action.user( 'Organizer', [ 'event-organizer' ] );, i.e., it creates an account and adds it to the event-organizer group, via the API. At this point I realized that we introduced the event-organizer somewhat recently (T376822), so it's possible that this test was already close to the 5s limit, and adding the user to a group pushed it even closer to that limit, hence intermittently failing depending on CI load. At this point I take a brief look at action.user() to see if it does anything special when requested to add a user to a group:
if (groups.length) { // HACK: This reduces the chance of race conditions due to // replication lag. For the proper solution, see T230211. await wiki.runAllJobs(); const groupResult = await root.addGroups(uname, groups); assert.sameMembers(groupResult.added, groups); }
Ewwwwwww it's emptying the job queue! There might be a slow job in there that's slowing everything down, but let's see the MW logs first. Note that the test patch was based on r1129873, which enables additional logging. No CLI requests are made during the test, so we're interested in mw-debug-web.log (and I did double-check that mw-debug-cli is semi-empty). I start by checking the times of each request (output below has been processed a bit):
2025-03-24 20:52:14 Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-03-24 20:52:15 Start request POST /api.php 2025-03-24 20:52:15 Start request GET /api.php?format=json&action=query&meta=tokens&type=createaccount%7Cuserrights%7Ccsrf 2025-03-24 20:52:15 Start request POST /api.php 2025-03-24 20:52:16 Start request POST /index.php 2025-03-24 20:52:16 Start request POST /index.php 2025-03-24 20:52:16 Start request POST /index.php 2025-03-24 20:52:17 Start request POST /index.php 2025-03-24 20:52:17 Start request POST /index.php 2025-03-24 20:52:17 Start request POST /api.php 2025-03-24 20:52:17 Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-03-24 20:52:17 Start request POST /api.php 2025-03-24 20:52:17 Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-03-24 20:52:18 Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-03-24 20:52:18 Start request POST /api.php 2025-03-24 20:52:18 Start request POST /api.php 2025-03-24 20:52:18 Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-03-24 20:52:18 Start request POST /api.php 2025-03-24 20:52:18 Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-03-24 20:52:18 Start request POST /api.php 2025-03-24 20:52:19 Start request POST /index.php 2025-03-24 20:52:19 Start request POST /index.php
Even without the POST payloads, we can tell that the GET request at 20:52:15 is obtaining a createaccount token, and the subsequent POST api.php is likely the account creation. We then have 5 POSTs to index.php spanning a couple seconds... These can only be the Special:RunJobs requests, and they're taking up a couple of seconds. This would already explain the timeouts. Let's dig deeper though, starting from the first index.php request at 20:52:16. The first thing I notice is that the logs are full of warnings like this:
2025-03-24 20:52:16 587e7eb491b2 wikidb: [844e3108d6dd56b49cf612d1] /index.php PHP Warning: filemtime(): stat failed for /workspace/src/extensions/WikimediaMessages/i18n/wikimedia/en-x-piglatin.json
#0 [internal function]: MWExceptionHandler::handleError(int, string, string, int, array)
#1 /workspace/src/includes/language/dependency/FileDependency.php(68): filemtime(string)
#2 /workspace/src/includes/language/dependency/FileDependency.php(58): FileDependency->loadDependencyValues()
#3 [internal function]: FileDependency->__sleep()
#4 /workspace/src/includes/language/LCStoreStaticArray.php(100): serialize(array)
#5 /workspace/src/includes/language/LCStoreStaticArray.php(61): LCStoreStaticArray::encode(array)
#6 /workspace/src/includes/language/LocalisationCache.php(1292): LCStoreStaticArray->set(string, array)
#7 /workspace/src/includes/language/LocalisationCache.php(614): LocalisationCache->recache(string)
#8 /workspace/src/includes/language/LocalisationCache.php(523): LocalisationCache->initLanguage(string)
#9 /workspace/src/includes/language/LocalisationCache.php(403): LocalisationCache->loadSubitem(string, string, string)
#10 /workspace/src/includes/language/MessageCache.php(683): LocalisationCache->getSubitem(string, string, string)
#11 /workspace/src/includes/language/MessageCache.php(1276): MessageCache->isMainCacheable(string, string)
#12 /workspace/src/includes/language/MessageCache.php(1159): MessageCache->getMsgFromNamespace(string, string)
#13 /workspace/src/includes/language/MessageCache.php(1132): MessageCache->getMessageForLang(string, string, bool, array)
#14 /workspace/src/includes/language/MessageCache.php(1036): MessageCache->getMessageFromFallbackChain(string, string, bool)
#15 /workspace/src/includes/language/Message/Message.php(1518): MessageCache->get(string, bool, string, string)
#16 /workspace/src/includes/language/Message/Message.php(1173): MediaWiki\Message\Message->fetchMessage()
#17 /workspace/src/includes/language/LanguageConverter.php(754): MediaWiki\Message\Message->exists()
#18 /workspace/src/includes/language/LanguageConverter.php(739): MediaWiki\Language\LanguageConverter->computeNsVariantText(int, string)
#19 /workspace/src/includes/libs/objectcache/BagOStuff.php(216): MediaWiki\Language\LanguageConverter->MediaWiki\Language\{closure}(int)
#20 /workspace/src/includes/language/LanguageConverter.php(740): Wikimedia\ObjectCache\BagOStuff->getWithSetCallback(string, int, Closure)
#21 /workspace/src/includes/language/Language.php(627): MediaWiki\Language\LanguageConverter->convertNamespace(int, string)
#22 /workspace/src/includes/language/Language.php(663): MediaWiki\Language\Language->getNamespaceAliases()
#23 /workspace/src/includes/language/Language.php(683): MediaWiki\Language\Language->getNamespaceIds()
#24 /workspace/src/includes/title/TitleParser.php(241): MediaWiki\Language\Language->getNsIndex(string)
#25 /workspace/src/includes/title/Title.php(2739): MediaWiki\Title\TitleParser->splitTitleString(string, int)
#26 /workspace/src/includes/title/Title.php(453): MediaWiki\Title\Title->secureAndSplit(string, int)
#27 /workspace/src/includes/title/Title.php(401): MediaWiki\Title\Title::newFromTextThrow(string, int)
#28 /workspace/src/includes/language/LanguageConverter.php(979): MediaWiki\Title\Title::newFromText(string, int)
#29 /workspace/src/includes/actions/ActionEntryPoint.php(252): MediaWiki\Language\LanguageConverter->findVariantLink(string, MediaWiki\Title\Title)
#30 /workspace/src/includes/actions/ActionEntryPoint.php(327): MediaWiki\Actions\ActionEntryPoint->parseTitle(MediaWiki\Request\WebRequest)
#31 /workspace/src/includes/actions/ActionEntryPoint.php(91): MediaWiki\Actions\ActionEntryPoint->getTitle()
#32 /workspace/src/includes/MediaWikiEntryPoint.php(202): MediaWiki\Actions\ActionEntryPoint->execute()
#33 /workspace/src/index.php(58): MediaWiki\MediaWikiEntryPoint->run()
#34 {main}In fact, we have one of these for each extension i18n piglatin file. These are silenced errors, only shown because I'm intentionally outputting all logs. I'm going to ignore these. Soon after, we have our first interesting queries:
2025-03-24 20:52:16 587e7eb491b2 wikidb: MediaWiki\JobQueue\JobQueueDB::doGetSiblingQueuesWithJobs [1.291ms] localhost:/workspace/db/quibble-mysql-m5ol1wve/socket: SELECT DISTINCT job_cmd FROM `job` WHERE job_cmd IN ('updateBetaFeaturesUserCounts','sendCampaignEmail','CampaignEventsFindPotentialInvitees','crosswikiSuppressUser','LocalRenameUserJob','LocalPageMoveJob','CentralAuthCreateLocalAccountJob','CentralAuthUnattachUserJob','GlobalVanishJob','checkuserLogTemporaryAccountAccess','checkuserPruneCheckUserDataJob','checkuserUpdateUserCentralIndexJob','checkuserStoreClientHintsDataJob','cirrusSearchDeletePages','cirrusSearchIncomingLinkCount','cirrusSearchLinksUpdate','cirrusSearchLinksUpdatePrioritized','cirrusSearchMassIndex','cirrusSearchOtherIndex','cirrusSearchElasticaWrite','cirrusSearchCheckerJob','cirrusSearchIndexArchive','cirrusSearchDeleteArchive','EchoNotificationJob','EchoNotificationDeleteJob','EchoPushNotificationRequest','flaggedrevs_CacheUpdate','newcomerTasksCacheRefreshJob','setUserMentorDatabaseJob','reassignMenteesJob','menteeOverviewUpdateDataForMentor','refreshUserImpactJob','notificationKeepGoingJob','notificationGetStartedJob','ipinfoLogIPInfoAccess','globalJsonLinksCachePurge','RecordLintJob','InitImageDataJob','securePollPopulateVoterList','securePollTallyElection','securePollLogAdminAction','securePollArchiveElection','securePollUnarchiveElection','webVideoTranscode','webVideoTranscodePrioritized','MessageGroupStatesUpdaterJob','MessageIndexRebuildJob','RebuildMessageIndexJob','MessageUpdateJob','PurgeMessageBundleDependencies','RebuildMessageGroupStatsJob','TtmServerMessageUpdateJob','TTMServerMessageUpdateJob','UpdateMessageBundle','UpdateMessageJob','UpdateTranslatorActivity','deletePage','refreshLinks','deleteLinks','htmlCacheUpdate','sendMail','enotifNotify','fixDoubleRedirect','AssembleUploadChunks','PublishStashedFile','ThumbnailRender','UploadFromUrl','recentChangesUpdate','refreshLinksPrioritized','refreshLinksDynamic','activityUpdateJob','categoryMembershipChange','clearUserWatchlist','watchlistExpiry','cdnPurge','userGroupExpiry','clearWatchlistNotifications','userOptionsUpdate','revertedTagUpdate','null','userEditCountInit','parsoidCachePrewarm','renameUserTable','renameUserDerived','renameUser','RenderTranslationPageJob','NonPrioritizedRenderTranslationPageJob','MoveTranslatableBundleJob','DeleteTranslatableBundleJob','UpdateTranslatablePageJob')
[...]
2025-03-24 20:52:16 587e7eb491b2 wikidb: MediaWiki\JobQueue\JobQueueDB::claimRandom [0.225ms] localhost:/workspace/db/quibble-mysql-m5ol1wve/socket: SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 2031384696) ORDER BY job_random DESC LIMIT 1So, this is indeed a request to Special:RunJobs. Then we have a lot of log lines which aren't easy to digest. Let's start with a list of what jobs are being executed (output slightly processed):
2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.262ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' LIMIT 60,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.225ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 2031384696) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.283ms] UPDATE `job` SET job_token = '7c8610278060a6f4b672ce4028844473',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '3' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.247ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 299845495) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.228ms] UPDATE `job` SET job_token = 'b89bb637f2ff7da28daf9aa785cd6ea5',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '11' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.681ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' LIMIT 153,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.594ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 907404235) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.564ms] UPDATE `job` SET job_token = 'a24260e201722c9af26e9eae6e978f7d',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '18' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.222ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' LIMIT 94,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.208ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random >= 1843184049) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.214ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random <= 1843184049) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.239ms] UPDATE `job` SET job_token = '9f0ff10b1168e12b8fc665eb4da440bc',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'recentChangesUpdate' AND job_id = '2' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.347ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' LIMIT 41,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.787ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 15689634) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.688ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 15689634) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.699ms] UPDATE `job` SET job_token = '4950e41c6b11ca28bda1334a6f385d6f',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '23' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.712ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random <= 1751239729) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.629ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random >= 1751239729) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.457ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' LIMIT 56,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.402ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' AND (job_random <= 98331700) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.402ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' AND (job_random >= 98331700) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.597ms] UPDATE `job` SET job_token = '6c85705ac26478dc815de4aaef6d7f44',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'enotifNotify' AND job_id = '22' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.422ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' LIMIT 20,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.417ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 1533961865) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.384ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random <= 1533961865) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.544ms] UPDATE `job` SET job_token = 'e7f1433b15db48c9b317da669d594f97',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_id = '19' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.531ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 268344617) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.636ms] UPDATE `job` SET job_token = 'fce29f96cd3c676b9aafaf6e12f22e02',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '14' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.509ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 1120570814) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.572ms] UPDATE `job` SET job_token = '39ba9fd90f724723a46bce6db9d41571',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '5' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.529ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1303235330) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.591ms] UPDATE `job` SET job_token = '19e98c5f1b6d9a165d73b97a5d1b9b08',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '26' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.29ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 1395929752) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.282ms] UPDATE `job` SET job_token = '0606191aace70104066f64b569aa4c76',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '13' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.285ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 1965768140) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.202ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 1965768140) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.247ms] UPDATE `job` SET job_token = '645f31758e76187bf139f100677308b2',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '12' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.282ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 154862402) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.304ms] UPDATE `job` SET job_token = 'cbeafb9ded9646a45d2a1a13a6b0f7e9',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_id = '21' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.26ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random <= 1102316643) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.267ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 1102316643) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.18ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_token = '' LIMIT 145,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.196ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_token = '' AND (job_random >= 2116596415) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.181ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_token = '' AND (job_random <= 2116596415) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.29ms] UPDATE `job` SET job_token = 'dfbf641a841f0964c0063e507254eb9b',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_id = '24' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.279ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1834031162) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.205ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1834031162) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.349ms] UPDATE `job` SET job_token = 'd109155d0656cb444e7c7bad8aa72f94',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '28' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.211ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' LIMIT 37,1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.207ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random <= 157274040) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.215ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random >= 157274040) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.227ms] UPDATE `job` SET job_token = 'aa2a654e4488d8c2e05c7d788eaacb86',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_id = '20' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.215ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 1973720411) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.21ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 1973720411) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.219ms] UPDATE `job` SET job_token = '7a7051c4ada87c4874068e6209a02db3',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '15' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.251ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 2122918826) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.267ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 2122918826) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.214ms] UPDATE `job` SET job_token = 'ac4d2a3ffae807ce3ea2568788082489',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '10' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.205ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 1252450138) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.208ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 1252450138) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.23ms] UPDATE `job` SET job_token = 'c6cef9ce90cbae8777a66dfb6e05d10f',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '16' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.228ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 13027705) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.218ms] UPDATE `job` SET job_token = '956b751d2fe498300361ff145e8957d6',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '1' AND job_token = '' 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.556ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 986716838) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:16 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.602ms] UPDATE `job` SET job_token = '4b01805576a24a7c88d444d6a389542f',job_token_timestamp = '20250324205216',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '7' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.477ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 265210576) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.464ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 265210576) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.536ms] UPDATE `job` SET job_token = '499cf335f7cfbe741e8fbee69ae6f3a9',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '27' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.641ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1760021397) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.565ms] UPDATE `job` SET job_token = '2d37e4208bce1ca49eb3e4f51d30ae77',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '29' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.472ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 441221873) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.489ms] UPDATE `job` SET job_token = '7f2e9d8576663afd779d0d8ff4a61187',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '4' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.493ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1403982433) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.472ms] UPDATE `job` SET job_token = '3a1a48902729c746444ea77df866fb40',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '34' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.461ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 451766839) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.428ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 451766839) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.538ms] UPDATE `job` SET job_token = 'f8f437e698df17683ad4ac79d5d2ec2a',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '8' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.578ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_token = '' AND (job_random <= 852216435) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.493ms] UPDATE `job` SET job_token = '5710b988d395954b24018eafcbdb6354',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchIncomingLinkCount' AND job_id = '35' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.499ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 304345760) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.46ms] UPDATE `job` SET job_token = '7b9acc56685c26e0a5b40765e2765792',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '17' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.499ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 46763643) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.475ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 46763643) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.537ms] UPDATE `job` SET job_token = '9f6425a04aa08c1cfc8e1da69314b7ee',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '9' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.525ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 302266301) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.417ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 302266301) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.453ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 1938204931) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.513ms] UPDATE `job` SET job_token = 'fd3df45093105f08c0997ae7c402f227',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '6' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.683ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1430061116) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.638ms] UPDATE `job` SET job_token = '09587338cd547ff62f034cfa9c4dfc0d',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '31' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.702ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1135877607) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.673ms] UPDATE `job` SET job_token = '62757c76ea54aa7498a62283618797db',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '30' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.357ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1625237580) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.291ms] UPDATE `job` SET job_token = 'd6d6a9745c1d3eee8cae4d5cbf746167',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '39' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.298ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1355853171) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.257ms] UPDATE `job` SET job_token = '35de7d0ddc919db2fc13627c634dc11a',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '40' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.264ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1348011207) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.23ms] UPDATE `job` SET job_token = '1e7ba65f3f3d6be2a928741b4c55f271',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '36' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.296ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1096602486) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.289ms] UPDATE `job` SET job_token = 'ffa4f940d9bfadf67b992af01f3b36b8',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '41' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.25ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1771514750) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.279ms] UPDATE `job` SET job_token = 'a5db23f3fd7e8a93045872bb21595abf',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '33' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.244ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1572329301) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.229ms] UPDATE `job` SET job_token = 'bbc70d2f5e14046c0d5dc610b8f0f63b',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '32' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.295ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 868571829) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.21ms] UPDATE `job` SET job_token = 'e35ab44dee8bfff643b6653901e41cf8',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '42' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.221ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1965673495) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.231ms] UPDATE `job` SET job_token = 'a42eef400cb8e53bc9ada3b2bd7a61a6',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '46' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.294ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 453201103) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.281ms] UPDATE `job` SET job_token = '7e398472aee242c5d8dffeff7585859f',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '25' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.677ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 688660270) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.556ms] UPDATE `job` SET job_token = '6bdabd88c3c4e735485c6fdd386641ca',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '47' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.57ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1840210417) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.519ms] UPDATE `job` SET job_token = '5aaacd845326f5d4b25bc5eb115576b8',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '48' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.593ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1560043886) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.519ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 1560043886) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.521ms] UPDATE `job` SET job_token = '01b5a00195cf488b99f335d662d3d904',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '49' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.42ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 1464503292) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.391ms] UPDATE `job` SET job_token = 'bbb63dfe51cbe8b77a5283202f8f823b',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '51' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.265ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 870105919) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.368ms] UPDATE `job` SET job_token = 'f33055bd1c71722a5e6f03b182b3419d',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '52' AND job_token = '' 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.323ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 757178057) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:17 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.281ms] UPDATE `job` SET job_token = '5c4d0116b1cdbc935078ee202b593d3b',job_token_timestamp = '20250324205217',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '44' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.652ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 1487288408) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [1.542ms] UPDATE `job` SET job_token = 'b8ef208a77d2f6efed6481bc66c50a11',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_id = '63' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.638ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random <= 961694555) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.285ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 961694555) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.395ms] UPDATE `job` SET job_token = 'a160886c02c94968054587ba9c873bae',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_id = '60' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.386ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' AND (job_random >= 341178308) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [1.601ms] UPDATE `job` SET job_token = '5ded39799c137e80d83146304b38bce8',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'enotifNotify' AND job_id = '59' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [1.009ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random >= 1111918460) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.906ms] UPDATE `job` SET job_token = '8de2c4095ebfbec5be56aea1d8e6a103',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_id = '61' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [4.601ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 1795204171) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.76ms] UPDATE `job` SET job_token = '98e8ab1205db86747b60c96075ffe817',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_id = '62' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.527ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random >= 2102598238) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.532ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'htmlCacheUpdate' AND job_token = '' AND (job_random <= 2102598238) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [9.546ms] UPDATE `job` SET job_token = 'd228923e7a5421183e5a423ac4434afa',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'htmlCacheUpdate' AND job_id = '65' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.822ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random >= 750239530) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.285ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchLinksUpdate' AND job_token = '' AND (job_random <= 750239530) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.801ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' AND (job_random <= 1947449058) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.295ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'enotifNotify' AND job_token = '' AND (job_random >= 1947449058) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [5.838ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random <= 1643115335) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.68ms] UPDATE `job` SET job_token = '9bfcde82e4e71d12f10044e86fc202f4',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'recentChangesUpdate' AND job_id = '55' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.943ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 2120509520) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.781ms] UPDATE `job` SET job_token = '2267421bb395c174f6c1476190a7d7d3',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '53' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.777ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random >= 970931660) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.479ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random <= 970931660) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.788ms] UPDATE `job` SET job_token = '4ffad128ea95d43ebaa6fc25cadf9e8a',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'recentChangesUpdate' AND job_id = '58' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.76ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random >= 1355842370) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.638ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'recentChangesUpdate' AND job_token = '' AND (job_random <= 1355842370) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.651ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_token = '' AND (job_random >= 807202788) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.684ms] UPDATE `job` SET job_token = 'b7ac833c5b5d2233e28440e399176547',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'checkuserUpdateUserCentralIndexJob' AND job_id = '56' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.345ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random >= 1757059230) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.28ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random <= 1757059230) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.347ms] UPDATE `job` SET job_token = '034263524b29c77e76e8b85c01c6e136',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_id = '57' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.253ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random >= 691689976) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.218ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 691689976) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.313ms] UPDATE `job` SET job_token = '182804b87444bc488fa990ede6ad7479',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '38' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.426ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_token = '' AND (job_random <= 344338437) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.317ms] UPDATE `job` SET job_token = '86be7e538bedd06cfe460bf46ed3ace0',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'cirrusSearchElasticaWrite' AND job_id = '50' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.652ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random >= 1956429147) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.995ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random <= 1956429147) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.541ms] UPDATE `job` SET job_token = 'ef388b68b41b0683a6d74ad1e8be9d4b',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_id = '54' AND job_token = '' 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.632ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random <= 423759566) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.26ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'EchoNotificationDeleteJob' AND job_token = '' AND (job_random >= 423759566) ORDER BY job_random ASC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.222ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'refreshUserImpactJob' AND job_token = '' LIMIT 226,1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.562ms] SELECT job_id,job_cmd,job_namespace,job_title,job_timestamp,job_params,job_random,job_attempts,job_token,job_token_timestamp,job_sha1 FROM `job` WHERE job_cmd = 'refreshUserImpactJob' AND job_token = '' AND (job_random <= 1804103014) ORDER BY job_random DESC LIMIT 1 2025-03-24 20:52:19 MediaWiki\JobQueue\JobQueueDB::claimRandom [0.351ms] UPDATE `job` SET job_token = '87295e8d2fda73ff82c27c1462bcc80c',job_token_timestamp = '20250324205219',job_attempts = job_attempts+1 WHERE job_cmd = 'refreshUserImpactJob' AND job_id = '64' AND job_token = ''
Well, that's a lot. I wasn't familiar with the claimRandom logic, but after a quick look it seems to work like this: it first tries to get a job using a random OFFSET in the query; if that fails (because there are few jobs), it falls back to picking the first job whose job_random value is greater than a predetermined random value; if that also fails, it falls back to the other direction (i.e., job_random <= predetermined_value). Then, it updates the row to signal that the job is being attempted. This explains why we have more than one query per job claimed. With some more processing, and excluding duplicated rows for the same job, we get the following ordered list of attempted jobs:
2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 cirrusSearchLinksUpdate 2025-03-24 20:52:16 recentChangesUpdate 2025-03-24 20:52:16 cirrusSearchElasticaWrite 2025-03-24 20:52:16 enotifNotify 2025-03-24 20:52:16 checkuserUpdateUserCentralIndexJob 2025-03-24 20:52:16 cirrusSearchLinksUpdate 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 cirrusSearchElasticaWrite 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 cirrusSearchLinksUpdate 2025-03-24 20:52:16 checkuserUpdateUserCentralIndexJob 2025-03-24 20:52:16 cirrusSearchIncomingLinkCount 2025-03-24 20:52:16 cirrusSearchElasticaWrite 2025-03-24 20:52:16 EchoNotificationDeleteJob 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 cirrusSearchLinksUpdate 2025-03-24 20:52:16 cirrusSearchLinksUpdate 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:16 htmlCacheUpdate 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchLinksUpdate 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchLinksUpdate 2025-03-24 20:52:17 cirrusSearchIncomingLinkCount 2025-03-24 20:52:17 htmlCacheUpdate 2025-03-24 20:52:17 htmlCacheUpdate 2025-03-24 20:52:17 cirrusSearchLinksUpdate 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:17 cirrusSearchElasticaWrite 2025-03-24 20:52:19 checkuserUpdateUserCentralIndexJob 2025-03-24 20:52:19 checkuserUpdateUserCentralIndexJob 2025-03-24 20:52:19 enotifNotify 2025-03-24 20:52:19 EchoNotificationDeleteJob 2025-03-24 20:52:19 cirrusSearchLinksUpdate 2025-03-24 20:52:19 htmlCacheUpdate 2025-03-24 20:52:19 recentChangesUpdate 2025-03-24 20:52:19 cirrusSearchElasticaWrite 2025-03-24 20:52:19 recentChangesUpdate 2025-03-24 20:52:19 checkuserUpdateUserCentralIndexJob 2025-03-24 20:52:19 EchoNotificationDeleteJob 2025-03-24 20:52:19 cirrusSearchElasticaWrite 2025-03-24 20:52:19 cirrusSearchElasticaWrite 2025-03-24 20:52:19 EchoNotificationDeleteJob 2025-03-24 20:52:19 refreshUserImpactJob
Grouping by job type and sorting:
cirrusSearchElasticaWrite: 26 htmlCacheUpdate: 10 cirrusSearchLinksUpdate: 9 checkuserUpdateUserCentralIndexJob: 5 EchoNotificationDeleteJob: 4 recentChangesUpdate: 3 enotifNotify: 2 cirrusSearchIncomingLinkCount: 2 refreshUserImpactJob: 1
This is quite large, considering that the wiki has literally been just created. Let's start by taking a look at what pages triggered the htmlCacheUpdate jobs, since those are easy to find (just search for the job name) and should tell us what pages exist on the wiki:
Template:FlowMention Template:LQT_post_imported_with_suppressed_user Template:LQT_Moved_thread_stub_converted_to_Flow Template:LQT_post_imported_with_different_signature_user Template:Wikitext_talk_page_converted_to_Flow Main_Page Template:LQT_page_converted_to_Flow Template:Archive_for_converted_wikitext_talk_page Template:Archive_for_converted_LQT_page Event:Event_page_4UMu11KcFh
Fantastic, 8 out of 10 are pages that Flow creates when installed. Oh am I waiting for T332022. I'm wondering if we could somehow skip creating those pages in CI, assuming nothing is using them. CampaignEvents seems to depend on Flow indirectly: CampaignEvents -> Translate -> VisualEditor -> DiscussionTools -> Thanks -> Flow. Anyway, the next thing I want to understand is why we're running 26 instances of cirrusSearchElasticaWrite. Grepping that is even more interesting:
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=23,timestamp=20250324205216) STARTING
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=23,timestamp=20250324205216) t=62 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=26,timestamp=20250324205216) STARTING
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=26,timestamp=20250324205216) t=9 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=28,timestamp=20250324205216) STARTING
2025-03-24 20:52:16 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=28,timestamp=20250324205216) t=13 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=27,timestamp=20250324205216) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=27,timestamp=20250324205216) t=12 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=29,timestamp=20250324205216) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=29,timestamp=20250324205216) t=7 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":2,"wiki":"wikidb","page_id":2,"namespace":10,"namespace_text":"Template","title":"FlowMention","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"2","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=34,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":2,"wiki":"wikidb","page_id":2,"namespace":10,"namespace_text":"Template","title":"FlowMention","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"2","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=34,timestamp=20250324205217) t=15 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=31,timestamp=20250324205216) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=31,timestamp=20250324205216) t=36 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=30,timestamp=20250324205216) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=30,timestamp=20250324205216) t=20 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=39,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=39,timestamp=20250324205217) t=10 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=40,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=40,timestamp=20250324205217) t=4 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":2,"wiki":"wikidb","page_id":2,"namespace":10,"namespace_text":"Template","title":"FlowMention","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"2","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=36,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":2,"wiki":"wikidb","page_id":2,"namespace":10,"namespace_text":"Template","title":"FlowMention","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"2","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=36,timestamp=20250324205217) t=4 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=41,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=41,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=33,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":6,"wiki":"wikidb","page_id":6,"namespace":10,"namespace_text":"Template","title":"LQT post imported with suppressed user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"6","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=33,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=32,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=32,timestamp=20250324205217) t=4 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=42,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=42,timestamp=20250324205217) t=4 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=46,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=46,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=25,timestamp=20250324205216) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=1 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=25,timestamp=20250324205216) t=13 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=47,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=47,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=48,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":7,"wiki":"wikidb","page_id":7,"namespace":10,"namespace_text":"Template","title":"LQT post imported with different signature user","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"7","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=48,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Dropped
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=49,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=2 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=49,timestamp=20250324205217) t=56 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=51,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=51,timestamp=20250324205217) t=7 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=52,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":9,"wiki":"wikidb","page_id":9,"namespace":10,"namespace_text":"Template","title":"Archive for converted wikitext talk page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"9","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849517 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=52,timestamp=20250324205217) t=4 error=ElasticaWrite job failed: Dropped
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=44,timestamp=20250324205217) STARTING
2025-03-24 20:52:17 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=3 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=44,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=53,timestamp=20250324205217) STARTING
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":8,"wiki":"wikidb","page_id":8,"namespace":10,"namespace_text":"Template","title":"Wikitext talk page converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"8","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=53,timestamp=20250324205217) t=22 error=ElasticaWrite job failed: Dropped
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":3,"wiki":"wikidb","page_id":3,"namespace":10,"namespace_text":"Template","title":"LQT Moved thread stub converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"3","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=38,timestamp=20250324205217) STARTING
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":3,"wiki":"wikidb","page_id":3,"namespace":10,"namespace_text":"Template","title":"LQT Moved thread stub converted to Flow","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"3","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849537 errorCount=0 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=38,timestamp=20250324205217) t=26 error=ElasticaWrite job failed: Requeued
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=50,timestamp=20250324205217) STARTING
2025-03-24 20:52:19 cirrusSearchElasticaWrite Special: method=sendData arguments=["general",[{"data":{"version":5,"wiki":"wikidb","page_id":5,"namespace":10,"namespace_text":"Template","title":"Archive for converted LQT page","timestamp":"2025-03-24T20:51:56Z","create_timestamp":"2025-03-24T20:51:56Z","redirect":[]},"params":{"_id":"5","_index":"","_cirrus_hints":{"BuildDocument_flags":0,"noop":{"version":"documentVersion"}}},"upsert":true}]] cluster=default jobqueue_partition=default-0 update_group=page update_kind=page_refresh root_event_time=1742849516 createdAt=1742849536 errorCount=4 retryCount=0 requestId=f83047a9bb4bcb171e3bb648 namespace=-1 title= (id=50,timestamp=20250324205217) t=5 error=ElasticaWrite job failed: DroppedCleaned up for readability:
2025-03-24 20:52:16: Template:Archive for converted wikitext talk page - STARTING 2025-03-24 20:52:16: Template:Archive for converted wikitext talk page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:16: Template:LQT post imported with different signature user - STARTING 2025-03-24 20:52:16: Template:LQT post imported with different signature user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:16: Template:LQT post imported with suppressed user - STARTING 2025-03-24 20:52:16: Template:LQT post imported with suppressed user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with different signature user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with different signature user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with suppressed user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with suppressed user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:FlowMention - STARTING 2025-03-24 20:52:17: Template:FlowMention - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - STARTING 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted LQT page - STARTING 2025-03-24 20:52:17: Template:Archive for converted LQT page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - STARTING 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted LQT page - STARTING 2025-03-24 20:52:17: Template:Archive for converted LQT page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:FlowMention - STARTING 2025-03-24 20:52:17: Template:FlowMention - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - STARTING 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with suppressed user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with suppressed user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with different signature user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with different signature user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted LQT page - STARTING 2025-03-24 20:52:17: Template:Archive for converted LQT page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with different signature user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with different signature user - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - STARTING 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted LQT page - STARTING 2025-03-24 20:52:17: Template:Archive for converted LQT page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:LQT post imported with different signature user - STARTING 2025-03-24 20:52:17: Template:LQT post imported with different signature user - error=ElasticaWrite job failed: Dropped 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - STARTING 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - STARTING 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - STARTING 2025-03-24 20:52:17: Template:Archive for converted wikitext talk page - error=ElasticaWrite job failed: Dropped 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - STARTING 2025-03-24 20:52:17: Template:Wikitext talk page converted to Flow - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:19: Template:Wikitext talk page converted to Flow - STARTING 2025-03-24 20:52:19: Template:Wikitext talk page converted to Flow - error=ElasticaWrite job failed: Dropped 2025-03-24 20:52:19: Template:LQT Moved thread stub converted to Flow - STARTING 2025-03-24 20:52:19: Template:LQT Moved thread stub converted to Flow - error=ElasticaWrite job failed: Requeued 2025-03-24 20:52:19: Template:Archive for converted LQT page - STARTING 2025-03-24 20:52:19: Template:Archive for converted LQT page - error=ElasticaWrite job failed: Dropped
So the pages are the same flow pages, but ALL these jobs are failing, and hence they're re-enqueued, except they fail again, and so on, and they end up running (and failing) up to 5 times each. Alright, that explains why we're spending ages processing the job queue. But let's see why these jobs are failing. From the first attempt, we have:
2025-03-24 20:52:16 sending 1 documents to the wikidb_general index(s) against wikidb_general took 1 millis. Requested via web for 2c33c9c64851a02e2ba8143c6550a3b8 by executor 840951780
2025-03-24 20:52:16 Search backend error during sending 1 documents to the wikidb_general index(s) after 1: http_exception: Couldn't connect to host, Elasticsearch down?
2025-03-24 20:52:16 Failed to update documents 9
#0 /workspace/src/vendor/ruflin/elastica/src/Request.php(183): Elastica\Transport\Http->exec(Elastica\Request, array)
#1 /workspace/src/vendor/ruflin/elastica/src/Client.php(545): Elastica\Request->send()
#2 /workspace/src/vendor/ruflin/elastica/src/Bulk.php(298): Elastica\Client->request(string, string, string, array, string)
#3 /workspace/src/extensions/CirrusSearch/includes/DataSender.php(270): Elastica\Bulk->send()
#4 /workspace/src/extensions/CirrusSearch/includes/Job/ElasticaWrite.php(178): CirrusSearch\DataSender->sendData(string, array)
#5 /workspace/src/extensions/CirrusSearch/includes/Job/JobTraits.php(139): CirrusSearch\Job\ElasticaWrite->doJob()
#6 /workspace/src/includes/jobqueue/JobRunner.php(375): CirrusSearch\Job\CirrusGenericJob->run()
#7 /workspace/src/includes/jobqueue/JobRunner.php(337): MediaWiki\JobQueue\JobRunner->doExecuteJob(CirrusSearch\Job\ElasticaWrite)
#8 /workspace/src/includes/jobqueue/JobRunner.php(232): MediaWiki\JobQueue\JobRunner->executeJob(CirrusSearch\Job\ElasticaWrite)
#9 /workspace/src/includes/specials/SpecialRunJobs.php(132): MediaWiki\JobQueue\JobRunner->run(array)
#10 /workspace/src/includes/specials/SpecialRunJobs.php(117): MediaWiki\Specials\SpecialRunJobs->doRun(array)
#11 /workspace/src/includes/specialpage/SpecialPage.php(729): MediaWiki\Specials\SpecialRunJobs->execute(null)
#12 /workspace/src/includes/specialpage/SpecialPageFactory.php(1737): MediaWiki\SpecialPage\SpecialPage->run(null)
#13 /workspace/src/includes/actions/ActionEntryPoint.php(499): MediaWiki\SpecialPage\SpecialPageFactory->executePath(string, MediaWiki\Context\RequestContext)
#14 /workspace/src/includes/actions/ActionEntryPoint.php(143): MediaWiki\Actions\ActionEntryPoint->performRequest()
#15 /workspace/src/includes/MediaWikiEntryPoint.php(202): MediaWiki\Actions\ActionEntryPoint->execute()
#16 /workspace/src/index.php(58): MediaWiki\MediaWikiEntryPoint->run()
#17 {main}So maybe a misconfiguration? At any rate, I don't need to dig any deeper in the logs. However, there's one last thing I want to check. This all started because the api-testing framework empties the job queue when requested to change user group membership. But why exactly does it do that? Git-blaming the comment led me to r537107, which removes a sleep and adds the runAllJobs call. The commit message does not give additional context beyond what is in the comment. Reading the linked task, T230211, it actually does explain why the call was added. However, the task is mostly focused on replicated environments, but CI (like most developer setups) do not use replication. On top of that, it's not fully clear to me what the relationship is between waiting for replication and emptying the job queue. Is it "process the jobqueue just to wait some time and eventually replication will have caught up"? I assume it must be something like that, because the account creation + user right change sequence does not depend on or fire any jobs, as far as I can tell. If that is the case, it would be nice if api-testing had a config flag to specify whether it should wait for replication; and we could set this to false in CI.
Summing up, what causes the timeout:
- We are adding a user to the event-organizer group. Before doing that, the api-testing framework runs all jobs in the jobqueue, apparently to wait for replication.
- During MW installation, Flow creates 10 templates
- For each template, we enqueue an additional htmlCacheUpdate job, and a cirrusSearchElasticaWrite job
- Cirrus jobs are failing in CI, for reasons yet unclear. Failing jobs are re-enqueued and can run up to 5 times each
- Overall, this results in 62 jobs being run before the test begins. These easily take a couple seconds
- The additional couple seconds spent emptying the jobqueue are enough to sometimes push the job duration over the threshold of 5 seconds
Action items:
Comment Actions
As for how to fix this in the short term:
- The api-testing change will likely require some discussion and a release. It shouldn't be too complicated, but it'll likely take some time.
- The CirrusSearch issue is beyond my understanding, so it all depends on whether and when someone will figure it out.
- So, I claimed the Flow task to stop creating templates in CI, which seems like it would be the simplest solution.
Comment Actions
Change #1131070 had a related patch set uploaded (by Daimona Eaytoy; author: Daimona Eaytoy):
[mediawiki/extensions/CampaignEvents@master] api-testing: increase timeout of failing test
Comment Actions
Change #1131070 abandoned by Daimona Eaytoy:
[mediawiki/extensions/CampaignEvents@master] api-testing: increase timeout of failing test
Reason:
Fixed in CirrusSearch: T389895
Comment Actions
The wait time has been reduced by resolving T389895: CirrusSearch no longer (re-)enqueues write jobs. In https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/41136/console, the before hook now runs in roughly 3 seconds (sample size of 1, but previously it failed basically every time):
15:20:18 POST /campaignevents/v0/event_registration 15:20:21 permission error 15:20:21 ✔ fails session check for anonymous users (52ms)
So I'm calling this resolved. Further improvements will come from T389894 (stop creating Flow templates and running more jobs for them) and T389898 (do not run all jobs when changing user rights).
Comment Actions
Things have got much better, but sadly, the test still fails from time to time. We'll probably need T389894 to get it to an acceptable level, while we wait for a permanent solution.
Comment Actions
It's amazing how T389894 was just resolved, and the test suddenly got even slower. I'm now trying to reproduce the timeout again with debug logging enabled to see if there's anything I missed.
Comment Actions
Reproduced on the first try using the same test patch, in https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/42051 (not saving the build; important information below). We see the same pattern of 4 seconds spent in getOrganizerUser():
13:04:06 POST /campaignevents/v0/event_registration 13:04:06 Start: Wed Apr 02 2025 13:04:06 GMT+0000 (Coordinated Universal Time) 13:04:10 Got organizer: Wed Apr 02 2025 13:04:10 GMT+0000 (Coordinated Universal Time)
Going straight to checking the jobs in mw-debug-log, we have:
2025-04-02 13:04:09 EchoNotificationDeleteJob 2025-04-02 13:04:09 recentChangesUpdate 2025-04-02 13:04:09 recentChangesUpdate 2025-04-02 13:04:09 enotifNotify 2025-04-02 13:04:09 htmlCacheUpdate 2025-04-02 13:04:09 checkuserUpdateUserCentralIndexJob 2025-04-02 13:04:09 checkuserUpdateUserCentralIndexJob 2025-04-02 13:04:09 EchoNotificationDeleteJob 2025-04-02 13:04:11 enotifNotify 2025-04-02 13:04:11 htmlCacheUpdate 2025-04-02 13:04:11 EchoNotificationDeleteJob 2025-04-02 13:04:11 recentChangesUpdate 2025-04-02 13:04:11 checkuserUpdateUserCentralIndexJob 2025-04-02 13:04:11 refreshUserImpactJob 2025-04-02 13:04:11 checkuserUpdateUserCentralIndexJob 2025-04-02 13:04:11 checkuserUpdateUserCentralIndexJob 2025-04-02 13:04:11 EchoNotificationDeleteJob 2025-04-02 13:04:11 EchoNotificationDeleteJob
which is non-trivial for a newly-created wiki, but it's not as bad as the 60+ jobs we had before. But wait! The first job is claimed at 13:04:09, which is already 3 seconds in. In fact, we have:
2025-04-02 13:04:06 Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-04-02 13:04:07 Start request POST /api.php 2025-04-02 13:04:07 Start request GET /api.php?format=json&action=query&meta=tokens&type=createaccount%7Cuserrights%7Ccsrf 2025-04-02 13:04:07 Start request POST /api.php 2025-04-02 13:04:09 Start request POST /index.php
So, while processing the jobqueue definitely makes this slower, the majority of the time is now spent actually creating the account. Debugging the performance of a request that takes 2 seconds isn't easy when the log resolution is 1 second, but I tried. Everything seemed OK, as in, there does not seem to be any particular query or feature that takes a lot of time compared to the others, with one possible exception:
2025-04-02 13:04:07 647637ae41cd wikidb: Loading Tor exit node list cold. 2025-04-02 13:04:07 647637ae41cd wikidb: GET: https://onionoo.torproject.org/details?type=relay&running=true&flag=Exit 2025-04-02 13:04:08 647637ae41cd wikidb: GET https://onionoo.torproject.org/details?type=relay&running=true&flag=Exit HTTP/1.1 - 200 NULL
This is TorBlock making an HTTP request to retrieve a list of Tor exit nodes. The elapsed time of the request isn't logged, and it crossing the seconds boundary could be a coincidence, but it's definitely suspicious. In fact, requests to that URL seem to take a few seconds, so it's a plausible cause. So, my next attempt would be to see if we can disable this in CI. If that doesn't help, I guess we'll need to accept that the setup is too slow and probably increase the timeout. T389898: api-testing: avoid processing the entire job queue when changing user rights would help but that's for the longer term. T389998 would also help by dropping all these dependencies, and that should be coming real soon.
Comment Actions
After making the change to TorBlock I re-submitted r1133206. It ran in https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/42067/console, and while it passed, it seems to be really close to the 5s timeout:
14:12:28 POST /campaignevents/v0/event_registration 14:12:33 permission error 14:12:33 ✔ fails session check for anonymous users (87ms)
Comment Actions
Despite non-test patches failing 100% of the times, when using the debug patch I could only reproduce the timeout on the 278th attempt, after 4x100 attempts where it did not fail. Anyway, in https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/42087/console we have:
16:09:26 POST /campaignevents/v0/event_registration 16:09:26 Start: Wed Apr 02 2025 16:09:26 GMT+0000 (Coordinated Universal Time) 16:09:31 Got organizer: Wed Apr 02 2025 16:09:31 GMT+0000 (Coordinated Universal Time)
So, same pattern. However, when I went to check the logs:
Start request GET /api.php?format=json&action=query&meta=tokens&type=login IP: 127.0.0.1 HTTP HEADERS: CONNECTION: close ACCEPT-ENCODING: gzip, deflate HOST: 127.0.0.1:9413 (end headers) 2025-04-02 16:09:26 1f2f67dc9395 wikidb: LocalisationCache using store LCStoreStaticArray 2025-04-02 16:09:29 1f2f67dc9395 wikidb: MainWANObjectCache using store Wikimedia\ObjectCache\MemcachedPhpBagOStuff
What is it doing in those ~3 seconds???
Comment Actions
I'm unable to reproduce this with 1000 runs in CI, and the failure above makes no sense. I'm going to tentatively close this and hope things will get better with T389998: Allow control over which extra extensions are installed (Math REL1_43 jobs exceed 60min timeout) and the switch to PHP 8.1 jobs.
Comment Actions
This keeps happening, unfortunately. Last occurrence is https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/44339/console for https://gerrit.wikimedia.org/r/c/mediawiki/extensions/CampaignEvents/+/1138751, same symptoms as before.
Comment Actions
Reproduced using the test patch: https://integration.wikimedia.org/ci/job/mediawiki-quibble-apitests-vendor-php74/44350/console (not preserved; relevant output below). It happened on the 300th iteration, which is surprising considering how I've seen the timeout for basically every "real" patch I pushed today; for at least one patch, it did not timeout but went really close (the time difference in the output, with 1s resolution, was exactly 5 seconds). Maybe it has to do with the current CI load. Anyway:
14:12:19 Start: 2025-04-24T14:12:19.069Z 14:12:24 1) "before all" hook in "POST /campaignevents/v0/event_registration" [... further down below...] 14:12:24 Got organizer: 2025-04-24T14:12:24.859Z
So, once again we're spending basically 100% of the time in the action.user() call. Checking mw-debug-web.log, we have the following requests:
2025-04-24 14:12:19.108: Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-04-24 14:12:19.175: Start request POST /api.php 2025-04-24 14:12:19.374: Start request GET /api.php?format=json&action=query&meta=tokens&type=createaccount%7Cuserrights%7Ccsrf 2025-04-24 14:12:19.417: Start request POST /api.php 2025-04-24 14:12:19.652: Start request POST /index.php 2025-04-24 14:12:19.718: Start request POST /api.php 2025-04-24 14:12:19.814: Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-04-24 14:12:19.871: Start request POST /api.php 2025-04-24 14:12:24.822: Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-04-24 14:12:24.878: Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-04-24 14:12:24.922: Start request POST /api.php 2025-04-24 14:12:25.162: Start request POST /api.php 2025-04-24 14:12:25.244: Start request GET /api.php?format=json&action=query&meta=tokens&type=login 2025-04-24 14:12:25.289: Start request POST /api.php 2025-04-24 14:12:25.494: Start request GET /api.php?format=json&action=query&meta=tokens&type=csrf 2025-04-24 14:12:25.542: Start request POST /api.php 2025-04-24 14:12:25.756: Start request POST /index.php 2025-04-24 14:12:25.865: Start request POST /index.php
Everything looks normal, except for the 2025-04-24 14:12:19.871 api.php request that took 5 seconds. Note that, unlike before, this has nothing to do with the job queue. Again, without the POST payloads we need to interpret the sequence a bit, but following the code, it seems to be logging in as root, so that it can then manage user groups. This makes sense because in the previous request it's obtaining a login token, and in the next request a csrf token (for user right management). So, why is it taking 5 seconds to login? Full logs for that request:
2025-04-24 14:12:19.871:
Start request POST /api.php
IP: 127.0.0.1
HTTP HEADERS:
CONNECTION: close
CONTENT-LENGTH: 128
COOKIE: wikidb_session=iuei79dq9apibbqrvinbu3s1t0rih5f0
CONTENT-TYPE: application/x-www-form-urlencoded
ACCEPT-ENCODING: gzip, deflate
HOST: 127.0.0.1:9413
(end headers)
2025-04-24 14:12:19.871: LocalisationCache using store LCStoreStaticArray
2025-04-24 14:12:19.872: SessionManager using store Wikimedia\ObjectCache\MemcachedPhpBagOStuff
2025-04-24 14:12:19.872: MainWANObjectCache using store Wikimedia\ObjectCache\MemcachedPhpBagOStuff
2025-04-24 14:12:19.872: MicroStash using store Wikimedia\ObjectCache\MemcachedPhpBagOStuff
2025-04-24 14:12:19.873: CentralAuthSessionProvider::provideSessionInfo: Not enabled, falling back to core sessions
2025-04-24 14:12:19.873: Session "iuei79dq9apibbqrvinbu3s1t0rih5f0" requested without UserID cookie
2025-04-24 14:12:19.873: get(wikidb:MWSession:iuei79dq9apibbqrvinbu3s1t0rih5f0)
2025-04-24 14:12:19.873: MemCache: sock i:0; got wikidb:MWSession:iuei79dq9apibbqrvinbu3s1t0rih5f0
2025-04-24 14:12:19.874: wgEventLoggingBaseUri has not been configured.
2025-04-24 14:12:19.876: MainObjectStash using store SqlBagOStuff
2025-04-24 14:12:19.876: MediaWiki\Parser\ParserFactory: using default preprocessor
2025-04-24 14:12:19.877: MediaWiki\Context\ContextSource::getContext (MediaWiki\Api\ApiModuleManager): called and $context is null. Using RequestContext::getMain()
2025-04-24 14:12:19.882: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.884: MessageCache using store Wikimedia\ObjectCache\MemcachedPhpBagOStuff
2025-04-24 14:12:19.886: MemCache: got WANCache:global:ipreputation-ipoid:127.0.0.1|#|v
2025-04-24 14:12:19.886: get(global:throttler:password:0:127.0.0.1:a1824f16f6373045c790bf32debd3fde)
2025-04-24 14:12:19.887: incr(global:throttler:password:0:127.0.0.1:a1824f16f6373045c790bf32debd3fde): NOT_FOUND
2025-04-24 14:12:19.887: add global:throttler:password:0:127.0.0.1:a1824f16f6373045c790bf32debd3fde (STORED)
2025-04-24 14:12:19.887: get(global:throttler:password:1:127.0.0.1:a1824f16f6373045c790bf32debd3fde)
2025-04-24 14:12:19.887: incr(global:throttler:password:1:127.0.0.1:a1824f16f6373045c790bf32debd3fde): NOT_FOUND
2025-04-24 14:12:19.887: add global:throttler:password:1:127.0.0.1:a1824f16f6373045c790bf32debd3fde (STORED)
2025-04-24 14:12:19.887: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" data dirty due to dirty(): MediaWiki\Auth\AuthManager->setAuthenticationSessionData/MediaWiki\Session\Session->setSecret/MediaWiki\Session\Session->getSecretKeys/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:19.887: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" data dirty due to dirty(): MediaWiki\Auth\AuthManager->setAuthenticationSessionData/MediaWiki\Session\Session->setSecret/MediaWiki\Session\Session->getSecretKeys/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:19.899: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" data dirty due to dirty(): MediaWiki\Auth\ThrottlePreAuthenticationProvider->testForAuthentication/MediaWiki\Auth\AuthManager->setAuthenticationSessionData/MediaWiki\Session\Session->setSecret/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:19.899: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" save: dataDirty=1 metaDirty=0 forcePersist=0
2025-04-24 14:12:19.899: client: serializing data as it is not scalar
2025-04-24 14:12:19.899: set wikidb:MWSession:iuei79dq9apibbqrvinbu3s1t0rih5f0 (STORED)
2025-04-24 14:12:19.911: MemCache: got WANCache:global:ipreputation-ipoid:127.0.0.1|#|v
2025-04-24 14:12:19.924: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" data dirty due to dirty(): MediaWiki\Api\ApiLogin->execute/MediaWiki\Auth\AuthManager->beginAuthentication/MediaWiki\Session\Session->setSecret/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:19.924: SessionBackend "iuei79dq9apibbqrvinbu3s1t0rih5f0" save: dataDirty=1 metaDirty=0 forcePersist=0
2025-04-24 14:12:19.924: client: serializing data as it is not scalar
2025-04-24 14:12:19.924: client: compressing data; was 3960 bytes is now 2963 bytes
2025-04-24 14:12:19.924: set wikidb:MWSession:iuei79dq9apibbqrvinbu3s1t0rih5f0 (STORED)
2025-04-24 14:12:19.937: MemCache: got WANCache:wikidb:messages:en:hash:v1|#|v
2025-04-24 14:12:19.937: MemCache: got WANCache:wikidb:messages:en|#|t
2025-04-24 14:12:19.937: get(wikidb:messages:en)
2025-04-24 14:12:19.937: MemCache: sock i:0; got wikidb:messages:en
2025-04-24 14:12:19.937: MessageCache::loadUnguarded: Loading en... local cache is empty, got from global cache
2025-04-24 14:12:19.937: MemCache: got WANCache:wikidb:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Flow--usertext|#|v
2025-04-24 14:12:19.938: MemCache: got WANCache:wikidb:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Flow-lock-usertext|#|v
2025-04-24 14:12:19.938: MemCache: got WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|v
2025-04-24 14:12:19.938: get(WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|i)
2025-04-24 14:12:19.938: MemCache: sock i:0; got WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|i
2025-04-24 14:12:19.938: add WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|m (STORED)
2025-04-24 14:12:19.940: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.941: Loading state for global user OrganizerssM3TFs91c from DB
2025-04-24 14:12:19.941: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.941: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.941: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.941: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.943: Loading attached wiki list for global user OrganizerssM3TFs91c from DB
2025-04-24 14:12:19.943: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.943: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.943: Loading groups for global user OrganizerssM3TFs91c
2025-04-24 14:12:19.944: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.944: MemCache: got WANCache:global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket|#|v
2025-04-24 14:12:19.944: client: serializing data as it is not scalar
2025-04-24 14:12:19.945: set WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|i (STORED)
2025-04-24 14:12:19.945: MemCache: delete WANCache:global:centralauth-user:a1824f16f6373045c790bf32debd3fde|#|m (DELETED)
2025-04-24 14:12:19.945: fetchOrRegenerate(global:centralauth-user:a1824f16f6373045c790bf32debd3fde): miss, new value computed
2025-04-24 14:12:19.945: Loading CentralAuthUser for user OrganizerssM3TFs91c from cache object
2025-04-24 14:12:19.945: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:19.945: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:19.950: MemCache: got WANCache:global:user:id:wikidb:602|#|v
2025-04-24 14:12:19.950: get(WANCache:global:user:id:wikidb:602|#|i)
2025-04-24 14:12:19.950: MemCache: sock i:0; got WANCache:global:user:id:wikidb:602|#|i
2025-04-24 14:12:19.950: add WANCache:global:user:id:wikidb:602|#|m (STORED)
2025-04-24 14:12:19.950: User: cache miss for user 602
2025-04-24 14:12:19.951: client: serializing data as it is not scalar
2025-04-24 14:12:19.951: set WANCache:global:user:id:wikidb:602|#|i (STORED)
2025-04-24 14:12:19.951: MemCache: delete WANCache:global:user:id:wikidb:602|#|m (DELETED)
2025-04-24 14:12:19.952: fetchOrRegenerate(global:user:id:wikidb:602): miss, new value computed
2025-04-24 14:12:19.953: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:19.954: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:19.954: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:19.956: getWithSetCallback(global:user:id:wikidb:602): process cache hit
2025-04-24 14:12:19.956: getWithSetCallback(global:user:id:wikidb:602): process cache hit
2025-04-24 14:12:19.981: authentication for 'OrganizerssM3TFs91c' succeeded
2025-04-24 14:12:19.981: Primary login with MediaWiki\Extension\CentralAuth\CentralAuthPrimaryAuthenticationProvider succeeded
2025-04-24 14:12:19.981: getWithSetCallback(global:user:id:wikidb:602): process cache hit
2025-04-24 14:12:19.982: OrganizerssM3TFs91c without email logging in
2025-04-24 14:12:19.982: Secondary login with MediaWiki\Extension\EmailAuth\EmailAuthSecondaryAuthenticationProvider succeeded
2025-04-24 14:12:20.006: Login for OrganizerssM3TFs91c succeeded from 127.0.0.1
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" metadata dirty due to ID reset (formerly "iuei79dq9apibbqrvinbu3s1t0rih5f0")
2025-04-24 14:12:20.007: MemCache: delete wikidb:MWSession:iuei79dq9apibbqrvinbu3s1t0rih5f0 (DELETED)
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->continueAuthentication/MediaWiki\Auth\AuthManager->setSessionDataForUser/MediaWiki\Session\Session->resetAllTokens/MediaWiki\Session\Session->remove/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" metadata dirty due to user change
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" metadata dirty due to remember-user change
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->beginAuthentication/MediaWiki\Auth\AuthManager->continueAuthentication/MediaWiki\Auth\AuthManager->setSessionDataForUser/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->beginAuthentication/MediaWiki\Auth\AuthManager->continueAuthentication/MediaWiki\Auth\AuthManager->setSessionDataForUser/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:20.007: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" save: dataDirty=1 metaDirty=1 forcePersist=0
2025-04-24 14:12:20.007: Persisting session for unknown reason
2025-04-24 14:12:20.007: setcookie: "wikidb_session", "htfaue40ep2ilu75iere9ekjuje1upv9", "0", "/", "", "", "1", ""
2025-04-24 14:12:20.007: setcookie: "wikidbUserID", "602", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.007: setcookie: "wikidbUserName", "OrganizerssM3TFs91c", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.007: setcookie: "wikidbToken", "5cdbecac3a8cc894f4e57288c6a61292", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.007: already set setcookie: "wikidb_session", "htfaue40ep2ilu75iere9ekjuje1upv9", "0", "/", "", "", "1", ""
2025-04-24 14:12:20.007: already set setcookie: "wikidbUserID", "602", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.007: already set setcookie: "wikidbUserName", "OrganizerssM3TFs91c", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.007: already set setcookie: "wikidbToken", "5cdbecac3a8cc894f4e57288c6a61292", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidb_session", "htfaue40ep2ilu75iere9ekjuje1upv9", "0", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbUserID", "602", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbUserName", "OrganizerssM3TFs91c", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbToken", "5cdbecac3a8cc894f4e57288c6a61292", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidb_session", "htfaue40ep2ilu75iere9ekjuje1upv9", "0", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbUserID", "602", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbUserName", "OrganizerssM3TFs91c", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: already set setcookie: "wikidbToken", "5cdbecac3a8cc894f4e57288c6a61292", "1761055940", "/", "", "", "1", ""
2025-04-24 14:12:20.008: client: serializing data as it is not scalar
2025-04-24 14:12:20.008: client: compressing data; was 3977 bytes is now 2959 bytes
2025-04-24 14:12:20.008: set wikidb:MWSession:htfaue40ep2ilu75iere9ekjuje1upv9 (STORED)
2025-04-24 14:12:20.020: MemCache: delete global:throttler:password:0:127.0.0.1:a1824f16f6373045c790bf32debd3fde (DELETED)
2025-04-24 14:12:24.736: MemCache: delete global:throttler:password:1:127.0.0.1:a1824f16f6373045c790bf32debd3fde (DELETED)
2025-04-24 14:12:24.764: Edge login on the next pageview after central login on shared domain
2025-04-24 14:12:24.764: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->callMethodOnProviders/MediaWiki\Extension\CentralAuth\CentralAuthPrimaryAuthenticationProvider->postAuthentication/MediaWiki\Request\WebRequest->setSessionData/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:24.765: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Api\ApiLogin->execute/MediaWiki\Auth\AuthManager->beginAuthentication/MediaWiki\Auth\AuthManager->continueAuthentication/MediaWiki\Session\Session->remove/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:24.765: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" save: dataDirty=1 metaDirty=0 forcePersist=0
2025-04-24 14:12:24.765: client: serializing data as it is not scalar
2025-04-24 14:12:24.765: set wikidb:MWSession:htfaue40ep2ilu75iere9ekjuje1upv9 (STORED)
2025-04-24 14:12:24.765: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->beginAuthentication/MediaWiki\Auth\AuthManager->continueAuthentication/MediaWiki\Auth\AuthManager->removeAuthenticationSessionData/MediaWiki\Session\Session->remove/MediaWiki\Session\SessionBackend->dirty
2025-04-24 14:12:24.765: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" save: dataDirty=1 metaDirty=0 forcePersist=0
2025-04-24 14:12:24.766: client: serializing data as it is not scalar
2025-04-24 14:12:24.766: set wikidb:MWSession:htfaue40ep2ilu75iere9ekjuje1upv9 (STORED)
2025-04-24 14:12:24.774: Found user OrganizerssM3TFs91c in table
2025-04-24 14:12:24.774: setcookie: "loginnotify_prevlogins", "2025-wh80mq-r27d0glwydo4ynv7bnsm26ritl11g93", "1761055944", "/", "", "", "1", ""
2025-04-24 14:12:24.775: Recording user OrganizerssM3TFs91c as known
2025-04-24 14:12:24.775: "main-account-login" "127.0.0.1" "127.0.0.1" "" ""
2025-04-24 14:12:24.776: Login attempt
2025-04-24 14:12:24.777: API POST 127.0.0.1 127.0.0.1 T=4899ms action=login format=json lgname=OrganizerssM3TFs91c lgpassword=[redacted] lgtoken=[redacted]
2025-04-24 14:12:24.777:
2025-04-24 14:12:24.778: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: primary transaction round committed
2025-04-24 14:12:24.778: DeferredUpdates::run: started MediaWiki\Deferred\MWCallableUpdate_MediaWiki\CheckUser\Services\CheckUserInsert->recordActionInCentralTablesOnDeferredUpdate #1326
2025-04-24 14:12:24.779: Loading state for global user OrganizerssM3TFs91c from DB
2025-04-24 14:12:24.779: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.779: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.779: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.779: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.780: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.780: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.780: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.780: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.781: Loading attached wiki list for global user OrganizerssM3TFs91c from DB
2025-04-24 14:12:24.781: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.781: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.781: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.781: getWithSetCallback(global:rdbms-server-readonly:localhost%3A/workspace/db/quibble-mysql-d1bu5uey/socket): process cache hit
2025-04-24 14:12:24.784: get(WANCache:global:jobqueue:wikidb:checkuserUpdateUserCentralIndexJob:rootjob:875d73920684ea91c8d27adec3abc7b807bb4198|#|v)
2025-04-24 14:12:24.784: client: serializing data as it is not scalar
2025-04-24 14:12:24.785: add WANCache:global:jobqueue:wikidb:checkuserUpdateUserCentralIndexJob:rootjob:875d73920684ea91c8d27adec3abc7b807bb4198|#|v (STORED)
2025-04-24 14:12:24.785: set global:jobqueue:wikidb:hasjobs:2 (STORED)
2025-04-24 14:12:24.785: set global:jobqueue:wikidb:hasjobs:1 (STORED)
2025-04-24 14:12:24.785: DeferredUpdates::run: ended MediaWiki\Deferred\MWCallableUpdate_MediaWiki\CheckUser\Services\CheckUserInsert->recordActionInCentralTablesOnDeferredUpdate #1326, processing time: 0.0072338581085205
2025-04-24 14:12:24.786: DeferredUpdates::run: started MediaWiki\Deferred\MWCallableUpdate_MediaWiki\Extension\EventLogging\EventSubmitter\EventBusEventSubmitter->submit #1307
2025-04-24 14:12:24.786: Selecting stream configs for target streams: mediawiki.accountcreation.login
2025-04-24 14:12:24.786: Stream 'mediawiki.accountcreation.login' does not match any `stream` in stream config
2025-04-24 14:12:24.786: Using non-producing EventBus instance for stream mediawiki.accountcreation.login. This stream is either undeclared, or is explicitly disabled.
2025-04-24 14:12:24.786: DeferredUpdates::run: ended MediaWiki\Deferred\MWCallableUpdate_MediaWiki\Extension\EventLogging\EventSubmitter\EventBusEventSubmitter->submit #1307, processing time: 0.00083303451538086
2025-04-24 14:12:24.787: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: pre-send deferred updates completed
2025-04-24 14:12:24.787: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: session changes committed
2025-04-24 14:12:24.787: add global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4:lock (STORED)
2025-04-24 14:12:24.787: get(global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4)
2025-04-24 14:12:24.787: MemCache: sock i:0; got global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4
2025-04-24 14:12:24.787: client: serializing data as it is not scalar
2025-04-24 14:12:24.787: set global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4 (STORED)
2025-04-24 14:12:24.788: MemCache: delete global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4:lock (DELETED)
2025-04-24 14:12:24.788: setcookie: "cpPosIndex", "5871@1745503944#2909a2c64757ce93daa60e3cfc653ef1", "1745503954", "/", "", "", "1", ""
2025-04-24 14:12:24.788: setcookie: "UseDC", "master", "1745503954", "/", "", "", "1", ""
2025-04-24 14:12:24.790: MemCache: got WANCache:wikidb:MediaWiki\Extension\CommunityConfiguration\Store\WikiPageStore:1:8:GrowthExperimentsMentorship.json|#|v
2025-04-24 14:12:24.793: Block cache miss with key BlockCacheKey{request=#580,user=#803,replica}
2025-04-24 14:12:24.800: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: primary transaction round committed
2025-04-24 14:12:24.800: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: pre-send deferred updates completed
2025-04-24 14:12:24.801: MediaWiki\MediaWikiEntryPoint::commitMainTransaction: session changes committed
2025-04-24 14:12:24.801: add global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4:lock (STORED)
2025-04-24 14:12:24.801: get(global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4)
2025-04-24 14:12:24.801: MemCache: sock i:0; got global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4
2025-04-24 14:12:24.801: client: serializing data as it is not scalar
2025-04-24 14:12:24.801: set global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4 (STORED)
2025-04-24 14:12:24.801: MemCache: delete global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4:lock (DELETED)
2025-04-24 14:12:24.801: setcookie: "cpPosIndex", "5872@1745503944#2909a2c64757ce93daa60e3cfc653ef1", "1745503954", "/", "", "", "1", ""
2025-04-24 14:12:24.801: already set setcookie: "UseDC", "master", "1745503954", "/", "", "", "1", ""
2025-04-24 14:12:24.802: Block cache hit with key BlockCacheKey{request=#580,user=#803,replica}
2025-04-24 14:12:24.802: Output buffer flushed
2025-04-24 14:12:24.802: FastCGI request finished
2025-04-24 14:12:24.802: DeferredUpdates::run: started MediaWiki\Deferred\MWCallableUpdate_Wikimedia\ObjectCache\MediumSpecificBagOStuff->trackDuplicateKeys #1713
2025-04-24 14:12:24.802: Duplicate get(): "global:Wikimedia\Rdbms\ChronologyProtector:2909a2c64757ce93daa60e3cfc653ef1:v4" fetched 2 times
2025-04-24 14:12:24.802: DeferredUpdates::run: ended MediaWiki\Deferred\MWCallableUpdate_Wikimedia\ObjectCache\MediumSpecificBagOStuff->trackDuplicateKeys #1713, processing time: 0.00013589859008789
2025-04-24 14:12:24.802: Request ended normally
2025-04-24 14:12:24.803: Saving all sessions on shutdownThe relevant part being:
2025-04-24 14:12:20.008: client: compressing data; was 3977 bytes is now 2959 bytes 2025-04-24 14:12:20.008: set wikidb:MWSession:htfaue40ep2ilu75iere9ekjuje1upv9 (STORED) 2025-04-24 14:12:20.020: MemCache: delete global:throttler:password:0:127.0.0.1:a1824f16f6373045c790bf32debd3fde (DELETED) 2025-04-24 14:12:24.736: MemCache: delete global:throttler:password:1:127.0.0.1:a1824f16f6373045c790bf32debd3fde (DELETED) 2025-04-24 14:12:24.764: Edge login on the next pageview after central login on shared domain 2025-04-24 14:12:24.764: SessionBackend "htfaue40ep2ilu75iere9ekjuje1upv9" data dirty due to dirty(): MediaWiki\Auth\AuthManager->callMethodOnProviders/MediaWiki\Extension\CentralAuth\CentralAuthPrimaryAuthenticationProvider->postAuthentication/MediaWiki\Request\WebRequest->setSessionData/MediaWiki\Session\Session->set/MediaWiki\Session\SessionBackend->dirty
So it seems to be spending 4.7 seconds deleting a key from memcached. Using the key name (and the string "throttler" in particular), it isn't hard to find where the key is defined and then deleted, in Throttler::clear:
public function clear( $username = null, $ip = null ) { $userKey = $username ? md5( $username ) : null; foreach ( $this->conditions as $index => $specificThrottle ) { $ipKey = isset( $specificThrottle['allIPs'] ) ? null : $ip; $throttleKey = $this->getThrottleKey( $this->type, $index, $ipKey, $userKey ); $this->cache->delete( $throttleKey ); } }
Both keys being deleted are for the same user, and they only differ in the index condition. Which presumably means those are two consecutive delete() calls from the loop above, without any other significant portion of code being executed in the meantime. And because the loop itself is trivial, and MemcachedBagOStuff::delete is also kinda trivial, this seems to indicate that the time is really spent contacting memcached (unsure at which stage of the request lifecycle).
I was a bit confused at first because I didn't see anything too suspicious around 14:12 in the load graphs for integration-agent-docker-1041: https://grafana.wmcloud.org/d/0g9N-7pVz/cloud-vps-project-board?orgId=1&var-project=integration&var-instance=integration-agent-docker-1041&from=1745457507931&to=1745522068464. But then I realized that those times in grafana are in the local timezone, not UTC; it says so in the time selector, which is not too visible, but it's better than nothing. Checking the right time (16:12 for me) shows a CPU spike, but it's only one of many spikes, and not even the worst. It's also interesting that right at 16:12, the free disk space on /srv hits a local minimum, 56.7%, down from 76.4% two minutes before. It's not a global minimum (it gets lower several other times) and there's still plenty of space available, but maybe the disk writes point to something intensive going on around that time? Maybe a noisy neighbour? At any rate, this time it doesn't seem to be a MW problem.
TLDR: apparently we have 5 seconds of latency deleting a key from memcached, and it seems to be an infrastructure issue (not MW). I don't know what to do about it, though.
Comment Actions
Next steps on this: I'd need a way to prove or disprove the memcached theory. Do we have metrics or other (performance) indicators for memcached in quibble?
Comment Actions
Unassigning because I don't know how to prove or disprove the above. The issue is still happening, and it seems especially likely when CI is under increased load.
Comment Actions
Change #1142627 had a related patch set uploaded (by Daimona Eaytoy; author: Daimona Eaytoy):
[mediawiki/extensions/CampaignEvents@master] api-testing: use sysop user instead of bespoke organizer account
Comment Actions
Change #1142627 merged by jenkins-bot:
[mediawiki/extensions/CampaignEvents@master] api-testing: use sysop user instead of bespoke organizer account
Comment Actions
I removed the addUserToGroup call, which should make the test more lightweight. I don't have the necessary knowledge, or time, to investigate the root cause further.
Comment Actions
Seen a lot lately, it just happened in gate-and-submit for r1163848 and others. But obviously it still hasn't happened after 200 runs of my debugging patch.