Page MenuHomePhabricator

LogicException: Process cache for 'en' should be set by now (on translatewiki.net pageviews)
Closed, ResolvedPublic

Description

Example trace. The page which this happens seems pretty random. Trace is always the same

[2020-07-25 12:11:19] exception.ERROR: [47f8c59cf179675ba94e7a68] /wiki/User_talk:GTNS   LogicException from line 409 of /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php: Process cache for 'en' should be set by now. {"exception":"[object] (LogicException(code: 0): Process cache for 'en' should be set by now. at /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php:409)
[stacktrace]
#0 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php(1091): MessageCache->load('en')
#1 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php(1017): MessageCache->getMsgFromNamespace('Cirrussearch-mo...', 'en')
#2 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php(988): MessageCache->getMessageForLang(Object(LanguageEn), 'cirrussearch-mo...', true, Array)
#3 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/cache/MessageCache.php(930): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'cirrussearch-mo...', true)
#4 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/language/Message.php(1304): MessageCache->get('cirrussearch-mo...', true, Object(LanguageEn))
#5 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/language/Message.php(1026): Message->fetchMessage()
#6 /srv/mediawiki/tags/2020-07-22_14:51:13/extensions/CirrusSearch/includes/Hooks.php(194): Message->isDisabled()
#7 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/libs/objectcache/BagOStuff.php(149): CirrusSearch\\Hooks::CirrusSearch\\{closure}(600)
#8 /srv/mediawiki/tags/2020-07-22_14:51:13/extensions/CirrusSearch/includes/Hooks.php(198): BagOStuff->getWithSetCallback('translatewiki_n...', 600, Object(Closure))
#9 /srv/mediawiki/tags/2020-07-22_14:51:13/extensions/CirrusSearch/includes/Hooks.php(94): CirrusSearch\\Hooks::overrideMoreLikeThisOptionsFromMessage()
#10 /srv/mediawiki/tags/2020-07-22_14:51:13/extensions/CirrusSearch/includes/Hooks.php(66): CirrusSearch\\Hooks::initializeForRequest(Object(WebRequest))
#11 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/HookContainer/HookContainer.php(320): CirrusSearch\\Hooks::onBeforeInitialize(Object(Title), NULL, Object(OutputPage), Object(User), Object(WebRequest), Object(MediaWiki))
#12 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/HookContainer/HookContainer.php(131): MediaWiki\\HookContainer\\HookContainer->callLegacyHook('BeforeInitializ...', Array, Array, Array)
#13 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/HookContainer/HookRunner.php(988): MediaWiki\\HookContainer\\HookContainer->run('BeforeInitializ...', Array)
#14 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/MediaWiki.php(196): MediaWiki\\HookContainer\\HookRunner->onBeforeInitialize(Object(Title), NULL, Object(OutputPage), Object(User), Object(WebRequest), Object(MediaWiki))
#15 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/MediaWiki.php(940): MediaWiki->performRequest()
#16 /srv/mediawiki/tags/2020-07-22_14:51:13/includes/MediaWiki.php(543): MediaWiki->main()
#17 /srv/mediawiki/tags/2020-07-22_14:51:13/index.php(53): MediaWiki->run()
#18 /srv/mediawiki/tags/2020-07-22_14:51:13/index.php(46): wfIndexMain()
#19 {main}
","exception_id":"47f8c59cf179675ba94e7a68","exception_url":"/wiki/User_talk:GTNS","caught_by":"entrypoint"} []
Impact
  • Affects translatewiki.net page views sometimes (via CirrusSearch).
  • Affects WMF xml dump generation (via ActiveAbstract, T268585).
  • Affects MediaWiki web requests during a Scap deplyment (via MessageBlobStore, T276461).
  • Affects Translate extension and translatewiki: ttmserver-export.php fails a lot

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes

The other task has a different backtrace. Based on that I'm fairly surely that CirrusSearch is not causing this.

The other task has a different backtrace. Based on that I'm faily surely that CirrusSearch is not causing this.

Guaranteed, ActiveAbstracts in no way involves CirrusSearch.

A batch of these showed up today. Here's the info for one:

Message: [YBgkSgpAAPQAAG-zJ6oAAABG] /w/rest.php/el.wiktionary.org/v3/page/pagebundle/%CE%BB%CE%B9%CE%BA%CE%BD%CE%AF%CE%B6%CF%89/4136250 LogicException: Process cache for 'el' should be set by now.
URL: https://el.wiktionary.org/w/rest.php/el.wiktionary.org/v3/page/pagebundle/%CE%BB%CE%B9%CE%BA%CE%BD%CE%AF%CE%B6%CF%89/4136250

Stack Trace
from /srv/mediawiki/php-1.36.0-wmf.28/includes/cache/MessageCache.php(409)
#0 /srv/mediawiki/php-1.36.0-wmf.28/includes/cache/MessageCache.php(1096): MessageCache->load(string)
#1 /srv/mediawiki/php-1.36.0-wmf.28/includes/cache/MessageCache.php(1023): MessageCache->getMsgFromNamespace(string, string)
#2 /srv/mediawiki/php-1.36.0-wmf.28/includes/cache/MessageCache.php(993): MessageCache->getMessageForLang(Language, string, boolean, array)
#3 /srv/mediawiki/php-1.36.0-wmf.28/includes/cache/MessageCache.php(935): MessageCache->getMessageFromFallbackChain(Language, string, boolean)
#4 /srv/mediawiki/php-1.36.0-wmf.28/includes/language/Message.php(1294): MessageCache->get(string, boolean, Language)
#5 /srv/mediawiki/php-1.36.0-wmf.28/includes/language/Message.php(851): Message->fetchMessage()
#6 /srv/mediawiki/php-1.36.0-wmf.28/includes/language/Message.php(980): Message->toString(string)
#7 /srv/mediawiki/php-1.36.0-wmf.28/includes/specials/SpecialVersion.php(337): Message->escaped()
#8 /srv/mediawiki/php-1.36.0-wmf.28/extensions/Scribunto/includes/engines/LuaCommon/SiteLibrary.php(33): SpecialVersion::getVersion(string, Language)
#9 /srv/mediawiki/php-1.36.0-wmf.28/extensions/Scribunto/includes/engines/LuaCommon/LuaEngine.php(516): Scribunto_LuaSiteLibrary->register()
#10 /srv/mediawiki/php-1.36.0-wmf.28/extensions/Scribunto/includes/engines/LuaCommon/LuaEngine.php(155): Scribunto_LuaEngine->instantiatePHPLibrary(string, string, boolean)
#11 /srv/mediawiki/php-1.36.0-wmf.28/extensions/Scribunto/includes/engines/LuaSandbox/LuaSandboxEngine.php(49): Scribunto_LuaEngine->load()
#12 /srv/mediawiki/php-1.36.0-wmf.28/extensions/Scribunto/includes/common/Hooks.php(127): Scribunto_LuaSandboxEngine->getResourceUsage(integer)
#13 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/Parser.php(3351): ScribuntoHooks::invokeHook(Parser, PPTemplateFrame_Hash, array)
#14 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/Parser.php(3036): Parser->callParserFunction(PPTemplateFrame_Hash, string, array)
#15 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/PPFrame_Hash.php(255): Parser->braceSubstitution(array, PPTemplateFrame_Hash)
#16 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/Parser.php(3225): PPFrame_Hash->expand(PPNode_Hash_Tree)
#17 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/PPFrame_Hash.php(255): Parser->braceSubstitution(array, PPFrame_Hash)
#18 /srv/mediawiki/php-1.36.0-wmf.28/includes/parser/Parser.php(2874): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#19 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/extension/src/Config/DataAccess.php(295): Parser->replaceVariables(string)
#20 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TT/TemplateHandler.php(1168): MWParsoid\Config\DataAccess->preprocessWikitext(MWParsoid\Config\PageConfig, string)
#21 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TT/TemplateHandler.php(1514): Wikimedia\Parsoid\Wt2Html\TT\TemplateHandler->fetchExpandedTpl(string)
#22 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TT/TemplateHandler.php(1577): Wikimedia\Parsoid\Wt2Html\TT\TemplateHandler->onTemplate(Wikimedia\Parsoid\Tokens\SelfclosingTagTk)
#23 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TT/TokenHandler.php(202): Wikimedia\Parsoid\Wt2Html\TT\TemplateHandler->onTag(Wikimedia\Parsoid\Tokens\SelfclosingTagTk)
#24 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TokenTransformManager.php(118): Wikimedia\Parsoid\Wt2Html\TT\TokenHandler->process(array)
#25 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TokenTransformManager.php(168): Wikimedia\Parsoid\Wt2Html\TokenTransformManager->processChunk(array)
#26 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/TokenTransformManager.php(166): Wikimedia\Parsoid\Wt2Html\TokenTransformManager->processChunkily(string, array)
#27 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/HTML5TreeBuilder.php(417): Wikimedia\Parsoid\Wt2Html\TokenTransformManager->processChunkily(string, array)
#28 [internal function]: Wikimedia\Parsoid\Wt2Html\HTML5TreeBuilder->processChunkily(string, array)
#29 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/DOMPostProcessor.php(900): Generator->current()
#30 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/ParserPipeline.php(178): Wikimedia\Parsoid\Wt2Html\DOMPostProcessor->processChunkily(string, array)
#31 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Wt2Html/ParserPipelineFactory.php(310): Wikimedia\Parsoid\Wt2Html\ParserPipeline->parseChunkily(string, array)
#32 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Core/WikitextContentModelHandler.php(106): Wikimedia\Parsoid\Wt2Html\ParserPipelineFactory->parse(string)
#33 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Parsoid.php(162): Wikimedia\Parsoid\Core\WikitextContentModelHandler->toDOM(Wikimedia\Parsoid\Config\Env)
#34 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/src/Parsoid.php(194): Wikimedia\Parsoid\Parsoid->parseWikitext(MWParsoid\Config\PageConfig, array)
#35 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/extension/src/Rest/Handler/ParsoidHandler.php(589): Wikimedia\Parsoid\Parsoid->wikitext2html(MWParsoid\Config\PageConfig, array, NULL)
#36 /srv/mediawiki/php-1.36.0-wmf.28/vendor/wikimedia/parsoid/extension/src/Rest/Handler/PageHandler.php(88): MWParsoid\Rest\Handler\ParsoidHandler->wt2html(MWParsoid\Config\PageConfig, array)
#37 /srv/mediawiki/php-1.36.0-wmf.28/includes/Rest/Router.php(395): MWParsoid\Rest\Handler\PageHandler->execute()
#38 /srv/mediawiki/php-1.36.0-wmf.28/includes/Rest/Router.php(322): MediaWiki\Rest\Router->executeHandler(MWParsoid\Rest\Handler\PageHandler)
#39 /srv/mediawiki/php-1.36.0-wmf.28/includes/Rest/EntryPoint.php(152): MediaWiki\Rest\Router->execute(MediaWiki\Rest\RequestFromGlobals)
#40 /srv/mediawiki/php-1.36.0-wmf.28/includes/Rest/EntryPoint.php(117): MediaWiki\Rest\EntryPoint->execute()
#41 /srv/mediawiki/php-1.36.0-wmf.28/rest.php(31): MediaWiki\Rest\EntryPoint::main()
#42 /srv/mediawiki/w/rest.php(3): require(string)
#43 {main}

These are two unrelated errors. They cause the same problem, but are not unrelated.

This task is about an error caused by CirrusSearch using a very early pre-setup hook in web-facing index.php entry points, to then trigger code that is likely not compatible with pre-setup execution contexts.

The above error is caused by Parsoid/Scribunto on the Rest entry point.

I'm getting this error when trying update my database from 1.31 to 1.35.

> php update.php
MediaWiki 1.35.1 Updater

[... runs successfully for a while ...]

Running maintenance/deduplicateArchiveRevId.php...
Deduplicating ar_rev_id...
LogicException from line 409 of /var/www/[mywiki]/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 /var/www/[mywiki]/includes/cache/MessageCache.php(1091): MessageCache->load()
#1 /var/www/[mywiki]/includes/cache/MessageCache.php(1017): MessageCache->getMsgFromNamespace()
#2 /var/www/[mywiki]/includes/cache/MessageCache.php(988): MessageCache->getMessageForLang()
#3 /var/www/[mywiki]/includes/cache/MessageCache.php(930): MessageCache->getMessageFromFallbackChain()
#4 /var/www/[mywiki]/includes/language/Message.php(1304): MessageCache->get()
#5 /var/www/[mywiki]/includes/language/Message.php(862): Message->fetchMessage()
#6 /var/www/[mywiki]/includes/language/Message.php(954): Message->toString()
#7 /var/www/[mywiki]/includes/Title.php(661): Message->text()
#8 /var/www/[mywiki]/maintenance/populateArchiveRevId.php(213): Title::newMainPage()
#9 /var/www/[mywiki]/maintenance/populateArchiveRevId.php(118): PopulateArchiveRevId::makeDummyRevisionRow()
#10 /var/www/[mywiki]/maintenance/deduplicateArchiveRevId.php(46): PopulateArchiveRevId::checkMysqlAutoIncrementBug()
#11 /var/www/[mywiki]/maintenance/includes/LoggedUpdateMaintenance.php(45): DeduplicateArchiveRevId->doDBUpdates()
#12 /var/www/[mywiki]/includes/installer/DatabaseUpdater.php(1151): LoggedUpdateMaintenance->execute()
#13 /var/www/[mywiki]/includes/installer/DatabaseUpdater.php(554): DatabaseUpdater->runMaintenance()
#14 /var/www/[mywiki]/includes/installer/DatabaseUpdater.php(517): DatabaseUpdater->runUpdates()
#15 /var/www/[mywiki]/maintenance/update.php(181): DatabaseUpdater->doUpdates()
#16 /var/www/[mywiki]/maintenance/doMaintenance.php(107): UpdateMediaWiki->execute()
#17 /var/www/[mywiki]/maintenance/update.php(253): require_once('/var/www/dev.pi...')
#18 {main}

>

In my case, the issue was a memcached instance silently failing to start. After fixing that, update.php succeeded without issue.

It seems like the error for this could have been more descriptive. The LogicException seems to be code (commented as a sanity check) which shouldn't be reached, but memcached being down is probably relatively common. Just above is this block:

if ( !$success ) {
	$where[] = 'loading FAILED - cache is disabled';
	$this->mDisable = true;
	$this->cache->set( $code, [] );
	$this->logger->error( __METHOD__ . ": Failed to load $code" );
	# This used to throw an exception, but that led to nasty side effects like
	# the whole wiki being instantly down if the memcached server died
}

Maybe this mitigation could be better implemented?

Seen today during page log dumps:

LogicException from line 412 of /srv/mediawiki/php-1.37.0-wmf.6/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 /srv/mediawiki/php-1.37.0-wmf.6/includes/cache/MessageCache.php(1113): MessageCache->load('en')
#1 /srv/mediawiki/php-1.37.0-wmf.6/includes/cache/MessageCache.php(1042): MessageCache->getMsgFromNamespace('Mainpage', 'en')
#2 /srv/mediawiki/php-1.37.0-wmf.6/includes/cache/MessageCache.php(1012): MessageCache->getMessageForLang(Object(LanguageEn), 'mainpage', true, Array)
#3 /srv/mediawiki/php-1.37.0-wmf.6/includes/cache/MessageCache.php(954): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'mainpage', true)
#4 /srv/mediawiki/php-1.37.0-wmf.6/includes/language/Message.php(1377): MessageCache->get('mainpage', true, Object(LanguageEn))
#5 /srv/mediawiki/php-1.37.0-wmf.6/includes/language/Message.php(895): Message->fetchMessage()
#6 /srv/mediawiki/php-1.37.0-wmf.6/includes/language/Message.php(987): Message->format('text')
#7 /srv/mediawiki/php-1.37.0-wmf.6/includes/Title.php(719): Message->text()
#8 /srv/mediawiki/php-1.37.0-wmf.6/includes/export/XmlDumpWriter.php(189): Title::newMainPage()
#9 /srv/mediawiki/php-1.37.0-wmf.6/includes/export/XmlDumpWriter.php(153): XmlDumpWriter->homelink()
#10 /srv/mediawiki/php-1.37.0-wmf.6/includes/export/XmlDumpWriter.php(143): XmlDumpWriter->siteInfo()
#11 /srv/mediawiki/php-1.37.0-wmf.6/includes/export/WikiExporter.php(151): XmlDumpWriter->openStream()
#12 /srv/mediawiki/php-1.37.0-wmf.6/maintenance/includes/BackupDumper.php(304): WikiExporter->openStream()
#13 /srv/mediawiki/php-1.37.0-wmf.6/maintenance/dumpBackup.php(88): BackupDumper->dump(8)
#14 /srv/mediawiki/php-1.37.0-wmf.6/maintenance/doMaintenance.php(108): DumpBackup->execute()
#15 /srv/mediawiki/php-1.37.0-wmf.6/maintenance/dumpBackup.php(144): require_once('/srv/mediawiki/...')
#16 /srv/mediawiki/multiversion/MWScript.php(116): require_once('/srv/mediawiki/...')
#17 {main}

Seen again today during the switchover (no obvious relation to databases or switchovers, red herring, but logging here as general issue that is still live traffic to fail for no apparent reason)

  • reqId: 4bc68cef-8ccd-4ad0-b991-1c4575b78422
normalized_message
[{reqId}] {exception_url}   LogicException: Process cache for 'de' should be set by now.
exception.trace
from /srv/mediawiki/php-1.37.0-wmf.11/includes/cache/MessageCache.php(414)
#0 /srv/mediawiki/php-1.37.0-wmf.11/includes/cache/MessageCache.php(1116): MessageCache->load(string)
#1 /srv/mediawiki/php-1.37.0-wmf.11/includes/cache/MessageCache.php(1045): MessageCache->getMsgFromNamespace(string, string)
#2 /srv/mediawiki/php-1.37.0-wmf.11/includes/cache/MessageCache.php(1015): MessageCache->getMessageForLang(Language, string, boolean, array)
#3 /srv/mediawiki/php-1.37.0-wmf.11/includes/cache/MessageCache.php(957): MessageCache->getMessageFromFallbackChain(Language, string, boolean)
#4 /srv/mediawiki/php-1.37.0-wmf.11/includes/language/Message.php(1398): MessageCache->get(string, boolean, Language)
#5 /srv/mediawiki/php-1.37.0-wmf.11/includes/language/Message.php(916): Message->fetchMessage()
#6 /srv/mediawiki/php-1.37.0-wmf.11/includes/language/Message.php(1008): Message->format(string)
#7 /srv/mediawiki/php-1.37.0-wmf.11/includes/OutputPage.php(946): Message->text()
#8 /srv/mediawiki/php-1.37.0-wmf.11/includes/OutputPage.php(995): OutputPage->setHTMLTitle(Message)
#9 /srv/mediawiki/php-1.37.0-wmf.11/includes/actions/Action.php(464): OutputPage->setPageTitle(string)
#10 /srv/mediawiki/php-1.37.0-wmf.11/includes/actions/FormlessAction.php(43): Action->setHeaders()
#11 /srv/mediawiki/php-1.37.0-wmf.11/includes/MediaWiki.php(538): FormlessAction->show()
#12 /srv/mediawiki/php-1.37.0-wmf.11/includes/MediaWiki.php(320): MediaWiki->performAction(Article, Title)
#13 /srv/mediawiki/php-1.37.0-wmf.11/includes/MediaWiki.php(925): MediaWiki->performRequest()
#14 /srv/mediawiki/php-1.37.0-wmf.11/includes/MediaWiki.php(559): MediaWiki->main()
#15 /srv/mediawiki/php-1.37.0-wmf.11/index.php(53): MediaWiki->run()
#16 /srv/mediawiki/php-1.37.0-wmf.11/index.php(46): wfIndexMain()
#17 /srv/mediawiki/w/index.php(3): require(string)
#18 {main}

Seeing a few of these today without any evident correlation with anything happening in the SAL. A spike of these messages on 5 different appservers, all on commonswiki, all within a few minutes. Same or similar stack trace.

Seems to be pretty consistent on labswiki when running a cirrus maint script, please see T288233

Trying to upgrade a wiki to 1.35 and seeing it consistently in AbuseFilter:

...afl_patrolled_by in table abuse_filter_log already modified by patch …/extensions/AbuseFilter/db_patches/patch-afl_change_deleted_patrolled.sql.
LogicException from line 406 of .../includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 .../includes/cache/MessageCache.php(1108): MessageCache->load('en')
#1 .../includes/cache/MessageCache.php(1034): MessageCache->getMsgFromNamespace('Abusefilter-blo...', 'en')
#2 .../includes/cache/MessageCache.php(1005): MessageCache->getMessageForLang(Object(LanguageEn), 'abusefilter-blo...', true, Array)
#3 .../includes/cache/MessageCache.php(947): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'abusefilter-blo...', true)
#4 .../includes/language/Message.php(1304): MessageCache->get('abusefilter-blo...', true, Object(LanguageEn))
#5 .../includes/language/Message.php(862): Message->fetchMessage()
#6 .../includes/language/Message.php(954): Message->toString('text')
#7 …/extensions/AbuseFilter/includes/AbuseFilterHooks.php(658): Message->text()
#8 .../includes/installer/DatabaseUpdater.php(554): AbuseFilterHooks::createAbuseFilterUser(Object(MysqlUpdater))
#9 .../includes/installer/DatabaseUpdater.php(522): DatabaseUpdater->runUpdates(Array, true)
#10 .../maintenance/update.php(181): DatabaseUpdater->doUpdates(Array)
#11 .../maintenance/doMaintenance.php(107): UpdateMediaWiki->execute()
#12 .../maintenance/update.php(253): require_once('....')
#13 {main}

In my case, the issue was a memcached instance silently failing to start. After fixing that, update.php succeeded without issue.

It seems like the error for this could have been more descriptive. The LogicException seems to be code (commented as a sanity check) which shouldn't be reached, but memcached being down is probably relatively common. Just above is this block:

if ( !$success ) {
	$where[] = 'loading FAILED - cache is disabled';
	$this->mDisable = true;
	$this->cache->set( $code, [] );
	$this->logger->error( __METHOD__ . ": Failed to load $code" );
	# This used to throw an exception, but that led to nasty side effects like
	# the whole wiki being instantly down if the memcached server died
}

Maybe this mitigation could be better implemented?

Thanks for this! I also migrated from 1.31 to 1.35 today, and my issue was also cache-related -- commenting out $wgMainCacheType = 'apcu' got my update.php past its own hurdle, which was in an entirely different section:

Beginning migration of revision.rev_user and revision.rev_user_text to revision_actor_temp.revactor_actor
LogicException from line 406 of /var/www/html/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
tstarling raised the priority of this task from Low to Medium.Aug 17 2021, 9:58 PM

Seems to be pretty consistent on labswiki when running a cirrus maint script, please see T288233

The followup on this ticket is that when a maintenance script is run against wikitech from mwmaint* the configured caches aren't available. This causes, at least in this specific instance, the Process cache for 'en' should be set by now. exception if that script triggers any i18n rendering.

Hi All

I encounter the issue during update from 1.36 to 1.37 @ update.php also as below

MediaWiki 1.37.2 Updater
....
LogicException from line 406 of /home/BARFOO/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 /home/BARFOO/includes/cache/MessageCache.php(1113): MessageCache->load('en')
#1 /home/BARFOO/includes/cache/MessageCache.php(1039): MessageCache->getMsgFromNamespace('Seconds-abbrev/...', 'en')
#2 /home/BARFOO/includes/cache/MessageCache.php(1010): MessageCache->getMessageForLang(Object(LanguageEn), 'seconds-abbrev', true, Array)
#3 /home/BARFOO/includes/cache/MessageCache.php(952): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'seconds-abbrev', true)
#4 /home/BARFOO/includes/language/Message.php(1393): MessageCache->get('seconds-abbrev', true, Object(LanguageEn))
#5 /home/BARFOO/includes/language/Message.php(911): Message->fetchMessage()
#6 /home/BARFOO/includes/language/Message.php(1003): Message->format('text')
#7 /home/BARFOO/languages/Language.php(4753): Message->text()
#8 /home/BARFOO/maintenance/update.php(217): Language->formatTimePeriod(2.6917719841003)
#9 /home/BARFOO/maintenance/doMaintenance.php(112): UpdateMediaWiki->execute()
#10 /home/BARFOO/maintenance/update.php(264): require_once('/home/www/www.e...')
#11 {main}

My issue is memcached instance also, update procedure success and work fine after commenting out cache relation options @ LocalSettings.php as below.

#$wgMainCacheType = CACHE_MEMCACHED;
#$wgParserCacheType = CACHE_MEMCACHED; # optional
#$wgMessageCacheType = CACHE_MEMCACHED; # optional
#$wgSessionCacheType = CACHE_MEMCACHED; # optional
#$wgMemCachedServers = array("unix:///var/run/memcached/memcached.sock:0");
#$wgSessionsInMemcached = true; # optional                                                                                                                                                              
#$wgSessionsInObjectCache = true; # optional

But got internal fault still after comment out removed.

Notice: Mencached running and work fine as below

# echo "stats" | nc -U var/run/memcached/memcached.sock
STAT pid 66
STAT uptime 5358
STAT time 1649238638
STAT version 1.6.14
STAT libevent 2.1.12-stable
STAT pointer_size 64
STAT rusage_user 1.216398
....

And memcached diagnostic result inside of Mediawiki as below

# php maintenance/mctest.php 
Warming up connections to cache servers...done
Single and batched operation profiling/test results:
unix:///var/run/memcached/memcached.sock:0
 add: 100/100 2ms   set: 100/100 2ms   incr: 100/100 1ms   get: 100/100 (2ms)   delete: 100/100 (1ms)
 setMulti (IB): ✓ 4ms   getMulti (IB): 100/100 1ms   changeTTLMulti (IB): ✓ 1ms   deleteMulti (IB): ✓ 1ms
 setMulti (DB): ✓ 4ms   getMulti (DB): 100/100 1ms   changeTTLMulti (DB): ✓ 1ms   deleteMulti (DB): ✓ 1ms

Thanks a lot.

We (Wiki Valley) had recently this error on MW 1.36, together with something like T280147 (we have $wgMainCacheType = CACHE_MEMCACHED like others here).

After some studying, here are some facts leading to this errror:

  • message cache has a TTL of 1 day, which explains this error comes again regularly,
  • before computing the message cache with the DB, a lock is acquired [to prevent cache stampede] but this lock is stored in Memcached (see MessageCache::loadFromDBWithLock(), MessageCache::getReentrantScopedLock(), BagOStuff::getScopedLock(), MediumSpecificBagOStuff::lock()), so if Memcached is disabled (or slow or cannot set a key for some reason) then this error occurs

Below are two partial resolutions.

  1. To prevent this error from occuring, I patched MessageCache::load() like the following, but it is only a degraded solution since the cache is deactivated and the server might become overloaded. This joins the @Jthile’s comment above T258860#6853093.
diff --git a/includes/cache/MessageCache.php b/includes/cache/MessageCache.php
@@ -403,7 +403,12 @@ class MessageCache implements LoggerAwareInterface {
 		}
 
 		if ( !$this->isLanguageLoaded( $code ) ) { // sanity
-			throw new LogicException( "Process cache for '$code' should be set by now." );
+			if ( $this->clusterCache instanceOf EmptyBagOStuff ) {
+				throw new LogicException( "Process cache for '$code' should be set by now." );
+			} else {
+				$this->clusterCache = ObjectCache::getInstance( CACHE_NONE );
+				return $this->load( $code, $mode );
+			}
 		}
 
 		$info = implode( ', ', $where );
  1. Another resolution, which seems to be better when the server is slow when creating the message cache, is to change the timeout of the lock. It is by default 30 seconds (MessageCache::LOCK_TTL) and increasing it seems to fix the issue on our side (if the warning Lock for <prefix>:messages:en held too long (34.0283 sec). appears, we can confidently say that this LOCK_TTL is too short for a given server with a given load).

I see two different actions to mitigate this issue:

  1. add a configuration parameter to customise the LOCK_TTL: this is an operational parameter and different servers have different powers, so it make sense to allow the sysadmin to customise this TTL,
  1. instead of throwing a LogicException, either the clusterCache could be deactivated like my previous comment, either the message overrides (in the MediaWiki: namespace) could be abandonned with MessageCache::disable(). Well, re-reading the code, I guess that, when we reach this LogicException, $this->mDisable was already set in any case, so re-calling load() with no clusterCache like I did is not usefull since the message cache is deactivated.

    So: either the mechanism is changed to have a two-stage degradation (first we try to read the message overrides, then if it failed, we disable message cache) either we disable directly the message cache. I find any of these solutions is better than the current behaviour of displaying a LogicException to the user, but a loud error might be triggered through a logger (level 3/error or even level 2/critical).

Change 793393 had a related patch set uploaded (by Nikerabbit; author: Nikerabbit):

[mediawiki/extensions/Translate@master] ttmserver-export: Add workaround for T258860

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

Change 793393 merged by jenkins-bot:

[mediawiki/extensions/Translate@master] ttmserver-export: Add workaround for T258860

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

Hi All

I tried to upgrade from 1.35.4 to latest of 1.35 series (1.35.7) and encounter the issue as below

MediaWiki 1.35.7 Updater
...
LogicException from line 406 of /home/www/www.epopen.com/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 /home/www/www.epopen.com/includes/cache/MessageCache.php(1108): MessageCache->load('en')
#1 /home/www/www.epopen.com/includes/cache/MessageCache.php(1034): MessageCache->getMsgFromNamespace('Seconds-abbrev/...', 'en')
#2 /home/www/www.epopen.com/includes/cache/MessageCache.php(1005): MessageCache->getMessageForLang(Object(LanguageEn), 'seconds-abbrev', true, Array)
#3 /home/www/www.epopen.com/includes/cache/MessageCache.php(947): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'seconds-abbrev', true)
#4 /home/www/www.epopen.com/includes/language/Message.php(1320): MessageCache->get('seconds-abbrev', true, Object(LanguageEn))
#5 /home/www/www.epopen.com/includes/language/Message.php(878): Message->fetchMessage()
#6 /home/www/www.epopen.com/includes/language/Message.php(970): Message->toString('text')
#7 /home/www/www.epopen.com/languages/Language.php(4637): Message->text()
#8 /home/www/www.epopen.com/maintenance/update.php(206): Language->formatTimePeriod(0.93422102928162)
#9 /home/www/www.epopen.com/maintenance/doMaintenance.php(107): UpdateMediaWiki->execute()
#10 /home/www/www.epopen.com/maintenance/update.php(253): require_once('/home/www/www.e...')

Encounter the issue first time at 1.35 series.

Thanks a lot.

I tried to upgrade latest of 1.38.

As previous mentioned, upgrade failed same when $wgMainCacheType="CACHE_MEMCACHED" as follows.

$wgMainCacheType = CACHE_MEMCACHED;
$wgParserCacheType = CACHE_MEMCACHED; # optional
$wgMessageCacheType = CACHE_MEMCACHED; # optional
$wgSessionCacheType = CACHE_MEMCACHED; # optional
$wgMemCachedServers = array("unix:///var/run/memcached/memcached.sock:0");
$wgSessionsInMemcached = true; # optional                                                                                                                                                              
$wgSessionsInObjectCache = true; # optional

Next, I tested to using follows instead.

$wgMainCacheType = CACHE_NONE;

Update successful and Mediawiki access successful.

However, got internal error after back to $wgMainCacheType="CACHE_MEMCACHED" even fresh(empty content) memcached server as follows.

[862cd2c9ab83e1602e6f6dc9] 2022-08-17 08:10:57: Fatal exception of type "LogicException"

Based on experiment result, Mediawiki can not work with CACHE_MEMCACHED right now.

I reproduce it with Quibble and REL1_38 with:

docker run \
  -v "$(pwd)/cache-nobody:/cache" \
  -v "$(pwd):/workspace" \
 -e ZUUL_URL=https://gerrit.wikimedia.org/r \
 -e ZUUL_PROJECT=mediawiki/core \
 -e ZUUL_BRANCH=REL1_38 \
 -e ZUUL_REF=REL1_38 \
docker-registry.wikimedia.org/releng/quibble-buster-php80:1.4.5-s2 \
 --packages-source=composer \
  --run=phpunit

The execution environment has php-memcached and the installer sets the cache to CACHE_MEMCACHED. When there is no memcached server running the localisation cache for en is not saved by the installer/updater. The fix for the above command is to use --entrypoint=quibble-with-supervisord which would spawn a memcached server.

Hi All

I tried to upgrade from 1.35.5 to 1.35.6 and encounter the issue as below

...RFC and PMID already added to interwiki database table.
...Update 'populate pp_sortkey' already logged as completed. Use --force to run it again.
...Update 'populate ip_changes' already logged as completed. Use --force to run it again.
...externallinks table indexes up to date
Set the local repo temp zone container to be private.
Purging caches...done.
LogicException from line 406 of /home/www/www.epopen.com/includes/cache/MessageCache.php: Process cache for 'en' should be set by now.
#0 /home/www/www.epopen.com/includes/cache/MessageCache.php(1108): MessageCache->load('en')
#1 /home/www/www.epopen.com/includes/cache/MessageCache.php(1034): MessageCache->getMsgFromNamespace('Seconds-abbrev/...', 'en')
#2 /home/www/www.epopen.com/includes/cache/MessageCache.php(1005): MessageCache->getMessageForLang(Object(LanguageEn), 'seconds-abbrev', true, Array)
#3 /home/www/www.epopen.com/includes/cache/MessageCache.php(947): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'seconds-abbrev', true)
#4 /home/www/www.epopen.com/includes/language/Message.php(1320): MessageCache->get('seconds-abbrev', true, Object(LanguageEn))
#5 /home/www/www.epopen.com/includes/language/Message.php(878): Message->fetchMessage()
#6 /home/www/www.epopen.com/includes/language/Message.php(970): Message->toString('text')
#7 /home/www/www.epopen.com/languages/Language.php(4637): Message->text()
#8 /home/www/www.epopen.com/maintenance/update.php(206): Language->formatTimePeriod(1.0091660022736)
#9 /home/www/www.epopen.com/maintenance/doMaintenance.php(107): UpdateMediaWiki->execute()
#10 /home/www/www.epopen.com/maintenance/update.php(253): require_once('/home/www/www.e...')
#11 {main}

Now, any upgrade impossible... (Tried 1.36/1.37/1.38 previous same failed)
I assume my data was corrupt but I no idea what/where.
Thanks a lot.

Hi All

In my case (using UNIX socket to access memcached), solution at https://phabricator.wikimedia.org/T320707 @taavi
Because string parse failed by new function since MW 1.35.6.

Thanks a lot.

We appear to have had had identical stack traces on wikibase.cloud (see: https://phabricator.wikimedia.org/T321051#8348898) which seem to have been caused by an inability for mediawiki to log into our redis instance (which at the moment is what $wgMainCacheType was set to for us). Resolving the log in credentials issue resolved this for us. I guess in general this error might be symptomatic of mediawiki being unable to connect to it's main cache.

I accidentally got my local wiki in a state where it consistently served this error on every page view and every CLI invocation. Upon turning off extensions and custom settings one-by-one, I narrowed it down to having Memcached configured but no Memcached running:

LocalSettings.php
$wgMainCacheType = CACHE_MEMCACHED;
$wgMemCachedServers = [ '127.0.0.1:11211', ];

The specific fact that I didn't have Memcached running is unimportant for this task, but I'm guessing the problem here is that there is an issue in MessageCache.php where if a certain one or two of its Memcached operations fail, it fatals completely.

My first guess would be that it might be needlessly storing and then retrieving its own value back during a cache miss, instead of keeping what generated for at least the current request, even if it can't store it.

I'm experiencing the same problem very occasionally on wikis using redis as the cache backend, and also on wikis with memcached backend. Both redis and memcached are fully functional and I don't see any error in redis logs.

My first guess would be that it might be needlessly storing and then retrieving its own value back during a cache miss, instead of keeping what generated for at least the current request, even if it can't store it.

Since objects stored in redis and memcached can disappear at any time, either because they expire or because they're evicted, I suspect occasional errors like this may happen when the object expires in the middle of the request. For example, the l10n cache is there at the start of the requests (when the cache is checked and populated if missing), but when accessed at a later time it has been expired/evicted and this error happens.

It's also very strange that this happens, because I've set $wgLocalisationCacheConf with store => files and a valid storeDirectory path, whith files recently written there. If the cache is stored on files, the cache should always be there, right?

I accidentally got my local wiki in a state where it consistently served this error on every page view and every CLI invocation. Upon turning off extensions and custom settings one-by-one, I narrowed it down to having Memcached configured but no Memcached running:

LocalSettings.php
$wgMainCacheType = CACHE_MEMCACHED;
$wgMemCachedServers = [ '127.0.0.1:11211', ];

The specific fact that I didn't have Memcached running is unimportant for this task, but I'm guessing the problem here is that there is an issue in MessageCache.php where if a certain one or two of its Memcached operations fail, it fatals completely.

My first guess would be that it might be needlessly storing and then retrieving its own value back during a cache miss, instead of keeping what generated for at least the current request, even if it can't store it.

The loadFromDBWithLock() method could return a different status for "lock I/O error", though I'm not sure what to do in that case. Running loadFromDBWithLock() has the risk of stampedes. Maybe an apcu lock could at least be used in that case as a middle ground.

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

[mediawiki/core@master] messagecache: better handle cluster cache lock key I/O errors

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

Change 886440 merged by jenkins-bot:

[mediawiki/core@master] MessageCache: improve handling of I/O errors from cache lock keys

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

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

[mediawiki/core@master] MessageCache: immediately update the local cache upon hash mismatch

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

Change 886441 merged by jenkins-bot:

[mediawiki/core@master] MessageCache: immediately update the local cache upon hash mismatch

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

Change 916871 had a related patch set uploaded (by Brian Wolff; author: Aaron Schulz):

[mediawiki/core@REL1_39] MessageCache: improve handling of I/O errors from cache lock keys

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

Change 916872 had a related patch set uploaded (by Brian Wolff; author: Aaron Schulz):

[mediawiki/core@REL1_39] MessageCache: immediately update the local cache upon hash mismatch

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

Change 916871 merged by jenkins-bot:

[mediawiki/core@REL1_39] MessageCache: improve handling of I/O errors from cache lock keys

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

Change 916872 merged by jenkins-bot:

[mediawiki/core@REL1_39] MessageCache: immediately update the local cache upon hash mismatch

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

Krinkle renamed this task from LogicException: Process cache for 'en' should be set by now to LogicException: Process cache for 'en' should be set by now (on translatewiki.net pageviews).Mar 27 2024, 10:16 PM