Page MenuHomePhabricator

PHP Fatal Error: Argument passed to MessageCache::isMainCacheable() must be array
Closed, ResolvedPublic

Description

Error

Request ID: W@Hz6gpAAEkAABH8J7gAAABE

message
PHP Fatal Error: Argument 2 passed to MessageCache::isMainCacheable() must be an instance of array, null given
trace
#0 /srv/mediawiki/php-1.33.0-wmf.2/includes/cache/MessageCache.php(1057): NO_FUNCTION_GIVEN()
#1 /srv/mediawiki/php-1.33.0-wmf.2/includes/cache/MessageCache.php(962): MessageCache->getMsgFromNamespace(string, string)
#2 /srv/mediawiki/php-1.33.0-wmf.2/includes/cache/MessageCache.php(931): MessageCache->getMessageForLang(Language, string, boolean, array)
#3 /srv/mediawiki/php-1.33.0-wmf.2/includes/cache/MessageCache.php(874): MessageCache->getMessageFromFallbackChain(Language, string, boolean)
#4 /srv/mediawiki/php-1.33.0-wmf.2/includes/Message.php(1299): MessageCache->get(string, boolean, Language)
#5 /srv/mediawiki/php-1.33.0-wmf.2/includes/Message.php(851): Message->fetchMessage()
#6 /srv/mediawiki/php-1.33.0-wmf.2/includes/Message.php(980): Message->toString(string)
#7 /srv/mediawiki/php-1.33.0-wmf.2/includes/Linker.php(1569): Message->escaped()
#8 /srv/mediawiki/php-1.33.0-wmf.2/includes/parser/Parser.php(4461): Linker::tocList(string, Language)
#9 /srv/mediawiki/php-1.33.0-wmf.2/includes/parser/Parser.php(1388): Parser->formatHeadings(string, string, boolean)
#10 /srv/mediawiki/php-1.33.0-wmf.2/includes/parser/Parser.php(482): Parser->internalParse(string)
#11 /srv/mediawiki/php-1.33.0-wmf.2/includes/StubObject.php(112): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#12 /srv/mediawiki/php-1.33.0-wmf.2/includes/StubObject.php(138): StubObject->_call(string, array)
#13 /srv/mediawiki/php-1.33.0-wmf.2/includes/content/WikitextContent.php(341): StubObject->__call(string, array)
#14 /srv/mediawiki/php-1.33.0-wmf.2/includes/content/AbstractContent.php(517): WikitextContent->fillParserOutput(Title, integer, ParserOptions, boolean, ParserOutput)
#15 /srv/mediawiki/php-1.33.0-wmf.2/includes/Revision/RenderedRevision.php(243): AbstractContent->getParserOutput(Title, integer, ParserOptions, boolean)
#16 /srv/mediawiki/php-1.33.0-wmf.2/includes/Revision/RenderedRevision.php(211): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached(WikitextContent, boolean)
#17 /srv/mediawiki/php-1.33.0-wmf.2/includes/Revision/RevisionRenderer.php(175): MediaWiki\Revision\RenderedRevision->getSlotParserOutput(string)
#18 /srv/mediawiki/php-1.33.0-wmf.2/includes/Revision/RevisionRenderer.php(128): MediaWiki\Revision\RevisionRenderer->combineSlotOutput(MediaWiki\Revision\RenderedRevision, array)
#19 [internal function]: Closure$MediaWiki\Revision\RevisionRenderer::getRenderedRevision#2(MediaWiki\Revision\RenderedRevision, array)
#20 /srv/mediawiki/php-1.33.0-wmf.2/includes/Revision/RenderedRevision.php(175): call_user_func(Closure$MediaWiki\Revision\RevisionRenderer::getRenderedRevision#2;1146, MediaWiki\Revision\RenderedRevision, array)
#21 /srv/mediawiki/php-1.33.0-wmf.2/includes/Storage/DerivedPageDataUpdater.php(1260): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#22 /srv/mediawiki/php-1.33.0-wmf.2/includes/Storage/DerivedPageDataUpdater.php(1602): MediaWiki\Storage\DerivedPageDataUpdater->getCanonicalParserOutput()
#23 /srv/mediawiki/php-1.33.0-wmf.2/includes/page/WikiPage.php(2066): MediaWiki\Storage\DerivedPageDataUpdater->doParserCacheUpdate()
#24 /srv/mediawiki/php-1.33.0-wmf.2/includes/api/ApiPurge.php(75): WikiPage->updateParserCache(array)
#25 /srv/mediawiki/php-1.33.0-wmf.2/includes/api/ApiMain.php(1570): ApiPurge->execute()
#26 /srv/mediawiki/php-1.33.0-wmf.2/includes/api/ApiMain.php(531): ApiMain->executeAction()
#27 /srv/mediawiki/php-1.33.0-wmf.2/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#28 /srv/mediawiki/php-1.33.0-wmf.2/api.php(87): ApiMain->execute()
#29 /srv/mediawiki/w/api.php(3): include(string)

Impact

API query from user was aborted due to a fatal error.

Notes

Seen in Logstash since 1.33-wmf.2. Appears to be specific to dewiki and /w/api.php requests.

Event Timeline

Krinkle created this task.Nov 6 2018, 9:01 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 6 2018, 9:01 PM
Krinkle added a subscriber: aaron.
Gilles added a subscriber: Gilles.Nov 16 2018, 1:13 PM

I think this is the likely culprit:

https://github.com/wikimedia/mediawiki/blob/master/includes/cache/MessageCache.php#L271

The PHP docs state that array_flip returns null if an error occurs. Language::getMessageKeysFor( $code ) must be returning something that isn't an array.

Under the same request id, I'm seeing a "Recursive link purge enqueued for MediaWiki:Gadgets-definition" log message. Which, imho, would suggest that the culprit request is an API purge of https://de.wikipedia.org/wiki/MediaWiki:Gadgets-definition I tried that in the API sandbox with the default parameters, but it doesn't seem to trigger the fatal: https://de.wikipedia.org/wiki/Spezial:ApiSandbox#action=purge&format=json&titles=MediaWiki%3AGadgets-definition

It would be nice if the logstash fatal entry contained the full URI used by the API request, it would avoid all the guesswork...

Gilles claimed this task.Nov 19 2018, 10:38 AM
Gilles triaged this task as Normal priority.

Change 474669 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/core@master] Log error when array_flip fails in MessageCache load

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

FYI in the case it is related: I am also seeing PHP Notice: Undefined index: sr-ec in /srv/mediawiki/tags/2018-11-14_07:55:54/includes/cache/MessageCache.php on line 1082 in translatewiki.net (so far seen for sr-ec, ckb, ru and bg=. Seen since Oct27.

Change 474669 merged by jenkins-bot:
[mediawiki/core@master] Log error when array_flip fails in MessageCache load

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

Imarlier moved this task from Inbox to Doing on the Performance-Team board.Nov 19 2018, 9:15 PM

Unless I'm querying logstash incorrectly, I don't see any occurence of the original fatal in the last 7 days.

Gilles closed this task as Resolved.Nov 30 2018, 12:29 PM

Please reopen if it's seen again.

Krinkle reopened this task as Open.Jul 24 2019, 6:15 PM

Still seen.

  • Exception ID: XTiGIgpAIDoAADqLlm0AAABD
  • de.wikipedia.org, POST, /w/api.php
[{exception_id}] {exception_url} PHP Fatal Error from line 1073 of /srv/mediawiki/php-1.34.0-wmf.14/includes/cache/MessageCache.php: Argument 2 passed to MessageCache::isMainCacheable() must be an instance of array, null given
#0 /srv/mediawiki/php-1.34.0-wmf.14/includes/cache/MessageCache.php(1073): NO_FUNCTION_GIVEN()
#1 /srv/mediawiki/php-1.34.0-wmf.14/includes/cache/MessageCache.php(978): MessageCache->getMsgFromNamespace(string, string)
#2 /srv/mediawiki/php-1.34.0-wmf.14/includes/cache/MessageCache.php(947): MessageCache->getMessageForLang(Language, string, boolean, array)
#3 /srv/mediawiki/php-1.34.0-wmf.14/includes/cache/MessageCache.php(890): MessageCache->getMessageFromFallbackChain(Language, string, boolean)
#4 /srv/mediawiki/php-1.34.0-wmf.14/includes/language/Message.php(1310): MessageCache->get(string, boolean, Language)
#5 /srv/mediawiki/php-1.34.0-wmf.14/includes/language/Message.php(865): Message->fetchMessage()
#6 /srv/mediawiki/php-1.34.0-wmf.14/includes/language/Message.php(957): Message->toString(string)
#7 /srv/mediawiki/php-1.34.0-wmf.14/includes/parser/ParserOutput.php(873): Message->text()
#8 /srv/mediawiki/php-1.34.0-wmf.14/includes/parser/Parser.php(4196): ParserOutput->addTrackingCategory(string, Title)
#9 /srv/mediawiki/php-1.34.0-wmf.14/includes/parser/Parser.php(4175): Parser->addTrackingCategory(string)
#10 /srv/mediawiki/php-1.34.0-wmf.14/includes/parser/Parser.php(1446): Parser->doDoubleUnderscore(string)
#11 /srv/mediawiki/php-1.34.0-wmf.14/includes/parser/Parser.php(555): Parser->internalParse(string)
#12 /srv/mediawiki/php-1.34.0-wmf.14/includes/content/WikitextContent.php(365): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#13 /srv/mediawiki/php-1.34.0-wmf.14/includes/content/AbstractContent.php(555): WikitextContent->fillParserOutput(Title, integer, ParserOptions, boolean, ParserOutput)
#14 /srv/mediawiki/php-1.34.0-wmf.14/includes/Revision/RenderedRevision.php(266): AbstractContent->getParserOutput(Title, integer, ParserOptions, boolean)
#15 /srv/mediawiki/php-1.34.0-wmf.14/includes/Revision/RenderedRevision.php(234): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached(WikitextContent, boolean)
#16 /srv/mediawiki/php-1.34.0-wmf.14/includes/Revision/RevisionRenderer.php(199): MediaWiki\Revision\RenderedRevision->getSlotParserOutput(string)
#17 /srv/mediawiki/php-1.34.0-wmf.14/includes/Revision/RevisionRenderer.php(148): MediaWiki\Revision\RevisionRenderer->combineSlotOutput(MediaWiki\Revision\RenderedRevision, array)
#18 [internal function]: Closure$MediaWiki\Revision\RevisionRenderer::getRenderedRevision#2(MediaWiki\Revision\RenderedRevision, array)
#19 /srv/mediawiki/php-1.34.0-wmf.14/includes/Revision/RenderedRevision.php(197): call_user_func(Closure$MediaWiki\Revision\RevisionRenderer::getRenderedRevision#2;2029, MediaWiki\Revision\RenderedRevision, array)
#20 /srv/mediawiki/php-1.34.0-wmf.14/includes/Storage/DerivedPageDataUpdater.php(1289): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#21 /srv/mediawiki/php-1.34.0-wmf.14/includes/Storage/DerivedPageDataUpdater.php(1647): MediaWiki\Storage\DerivedPageDataUpdater->getCanonicalParserOutput()
#22 /srv/mediawiki/php-1.34.0-wmf.14/includes/page/WikiPage.php(2089): MediaWiki\Storage\DerivedPageDataUpdater->doParserCacheUpdate()
#23 /srv/mediawiki/php-1.34.0-wmf.14/includes/api/ApiPurge.php(75): WikiPage->updateParserCache(array)
#24 /srv/mediawiki/php-1.34.0-wmf.14/includes/api/ApiMain.php(1583): ApiPurge->execute()
#25 /srv/mediawiki/php-1.34.0-wmf.14/includes/api/ApiMain.php(531): ApiMain->executeAction()
#26 /srv/mediawiki/php-1.34.0-wmf.14/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#27 /srv/mediawiki/php-1.34.0-wmf.14/api.php(86): ApiMain->execute()
#28 /srv/mediawiki/w/api.php(3): include(string)
#29 {main}
What we know

The fatal error is due to MessageCache::isMainCacheable being called with null as second parameter, instead of the required array.

The problematic call looks like MessageCache::isMainCacheable(…, $this->overridable) and lives on line 1073 of MessageCache.php. It is inside the MessageCache->getMsgFromNamespace method, which looks as follows:

	public function getMsgFromNamespace( $title, $code ) {
		// …
		$this->load( $code );

		if ( $entry !== null ) {
			// …
		} else {
			if ( !$this->isMainCacheable( $title, $this->overridable ) ) {

The class definition itself is as follows:

class MessageCache {
	// …
	protected $cache;

	// …
	protected $overridable;

	// …
	public function __construct() {
		$this->cache = new MapCacheLRU( 5 ); // …
		// …
	}

This means:

  1. It is normal to be able to call a MessageCache method when $this->overridable is null. This is because it has no default value and the constructor does not set it. This is okay. The overridable array is potentially expensive to compute and there is also not a good default we can use. This means while it can be null, it is up to the calling code to make sure it has been loaded before calling a method that depends on it.
  2. The usage we know is broken, in getMsgFromNamespace(), always calls MessageCache->load first. Maybe that will populate $this->overridable for us?

Let's take a look:

	protected function load( $code,  ) {
		// …
		if ( $this->cache->has( $code ) &&  ) {
			return;
		}

		$this->overridable = array_flip( Language::getMessageKeysFor( $code ) );

		// … Log for T208897 (this task)
		if ( $this->overridable === null ) {
			LoggerFactory::getInstance( 'MessageCache' )->error( '$this->overridable is null', [  ] );
		}

		// …
		if ( sometimes… ) {
			$this->cache->set( $code,  );
		}

This looks pretty good at first. We see it sets $this->overridable, which is what we want. We also see that it skips this and returns early, if cache says we have already loaded for $code before, which the bottom of the load() function indicates via cache->set(). So far so good.

The general problem

Presumably, the issue must be that our expectation is violated somewhere due to cache->set() being called outside this method – without setting up things like $this->overridable.

I've also checked the logging channel that an earlier patch on this task introduced but no errors have been logged there, which confirms that array_flip and this code in general within load() is working fine when it gets called, and supports the idea that something is causing cache->has() to think we have loaded this already.

Rule out obvious violations of cache->set

Calls to $this->cache->set actually do exist outside the MessageCache->load method. In these two methods:

  • MessageCache->refreshAndReplaceInternal
  • MessageCache->loadFromDBWithLock

The refreshAndReplaceInternal method is public and only used in one file in all of Wikimedia Git - namely in mediawiki-core/MessageCacheUpdate.php. That is a DeferredUpdate, which does not match the stack trace we have. The trace we have is from a web requests before any DeferredUpdates can run. In addition to that, looking at refreshAndReplaceInternal more closely, it always calls MessageCache->load(). It is a wrapper and should be as good as calling load(), which sets $this->overridable. So not the cause of our problem.

The loadFromDBWithLock method is protected and only used inside MessageCache->load. Hence, that is also a dead-end.

Back to the problem. What does MapCacheLRU do anyway?

If cache->set() is not the issue. What is?

The way that MessageCache->load determines whether cache->set() has been called is by checking cache->has( $code ). The cache object here is an instance of MapCacheLRU.

We must find when has() is maybe returning true when we don't expect it. The has() method checks for a key existing and not having expired. The expiration logic is unlikely to be the cause of our problem, because it would only cause has() to return true less often, not more often.

The set() method sets the key, fine. The get() method also looks fine.

But then, there is the MapCacheLRU->setField() method. Let's look at that:

From MapCacheLRU.php
	public function setField( $key, $field, $value,  ) {
		if ( !$this->has( $key ) ) {
			$this->set( $key, [],  );
		}

		$this->cache[$key][$field] = $value;

		// …

This means when calling setField($code, $something, $value) it will also initialise cache->set($code, []) and thus make cache->has($code) return true.

This might be a problem. For example, if MessageCache is using setField in places without doing load() as well.

And.... Yes, it is!

In MessageCache->replace() it will call setField($code, $something, …) without ensuring any of load() has happened. Thus making any future demand on load() result in it skipping the load process despite it not having occurred yet.

How did this happen

It started in Jan 2017 when change 318489 removed the call to MessageCache->load from MessageCache->replace. At the time, this was okay because the internal cache member worked differently than it does today. In 2017, cache was an array (not MapCacheLRU), and there was also a mLoadedLanguages list separately from cache. All expectations were met. The mLoadedLanguages list was only updated when load() happened. No problem.

Then, in July 2018, change 441842 removed cache (array) and mLoadedLanguages (array) in favour of a single MapCacheLRU where having a the top of the structure of a key in cache would be a proxy for a language being loaded. Which used to be true before Jan 2017, but not anymore.

Change 526198 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Krinkle claimed this task.Jul 29 2019, 6:25 PM

Change 526260 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.34.0-wmf.15] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Change 526198 merged by jenkins-bot:
[mediawiki/core@master] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Change 526260 merged by jenkins-bot:
[mediawiki/core@wmf/1.34.0-wmf.15] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Mentioned in SAL (#wikimedia-operations) [2019-07-29T22:33:48Z] <krinkle@deploy1001> Synchronized php-1.34.0-wmf.15/includes/cache/MessageCache.php: T208897 - fa817b088e43975 (duration: 00m 47s)

Krinkle closed this task as Resolved.Jul 30 2019, 3:13 PM
Krinkle removed a project: Patch-For-Review.
Prod added a subscriber: Prod.EditedAug 16 2019, 2:00 AM

I'm having this issue on 1.32. Can it be backported?

PHP Fatal error:  Uncaught TypeError: Argument 2 passed to MessageCache::isMainCacheable() must be of the type array, null given, called in w/includes/cache/MessageCache.php on line 1054 and defined in w/includes/cache/MessageCache.php:579
Stack trace:
#0 w/includes/cache/MessageCache.php(1054): MessageCache->isMainCacheable('internalerror', NULL)
#1 w/includes/cache/MessageCache.php(958): MessageCache->getMsgFromNamespace('Internalerror', 'en')
#2 w/includes/cache/MessageCache.php(928): MessageCache->getMessageForLang(Object(LanguageEn), 'internalerror', true, Array)
#3 w/includes/cache/MessageCache.php(870): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'internalerror', true)
#4 w/includes/Message.php(1299): MessageCache->get('internalerror', true, Object(LanguageEn))
#5 w/includes/Message in w/includes/cache/MessageCache.php on line 579, referer: https://......./w/index.php?title=MediaWiki:Common.css&action=submit

Change 530560 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@REL1_33] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Change 530561 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@REL1_32] MessageCache: Restore 'loadedLanguages' tracking for load()

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

I'm having this issue on 1.32. Can it be backported?

Sure. The regression (97e86d934b3) was first released in 1.32.0. So this should be safe to backport to 1.32 and 1.33.

Prod awarded a token.Aug 17 2019, 1:32 AM

Change 530560 merged by jenkins-bot:
[mediawiki/core@REL1_33] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Change 530561 merged by jenkins-bot:
[mediawiki/core@REL1_32] MessageCache: Restore 'loadedLanguages' tracking for load()

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

Krinkle closed this task as Resolved.Aug 17 2019, 3:14 PM
mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:08 PM