Page MenuHomePhabricator

array_keys() expects parameter 1 to be array, null given in cache/MessageCache.php on line 493
Closed, ResolvedPublic

Description

Log from Translatewiki.net,

","exception_id":"1189ee8b06d3ca69fc3fcf12","exception_url":"/w/i.php?title=Special:Translations&message=MediaWiki%3AUpload","caught_by":"mwe_handler"} []
[18-Aug-2019 12:19:45 UTC] PHP Warning:  array_keys() expects parameter 1 to be array, null given in /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php on line 493
[2019-08-18 12:19:45] error.ERROR: [1189ee8b06d3ca69fc3fcf12] /w/i.php?title=Special:Translations&message=MediaWiki%3AUpload   ErrorException from line 494 of /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php: PHP Warning: Invalid argument supplied for foreach() {"exception":"[object] (ErrorException(code: 0): PHP Warning: Invalid argument supplied for foreach() at /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php:494)
[stacktrace]
#0 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(494): MWExceptionHandler::handleError(2, 'Invalid argumen...', '/srv/mediawiki/...', 494, Array)
#1 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(439): MessageCache->loadFromDB('yua', NULL)
#2 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(359): MessageCache->loadFromDBWithLock('yua', Array, NULL)
#3 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(1049): MessageCache->load('yua')
#4 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(976): MessageCache->getMsgFromNamespace('Translate-docum...', 'yua')
#5 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(946): MessageCache->getMessageForLang(Object(Language), 'translate-docum...', true, Array)
#6 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/cache/MessageCache.php(888): MessageCache->getMessageFromFallbackChain(Object(Language), 'translate-docum...', true)
#7 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/language/Message.php(1310): MessageCache->get('translate-docum...', true, Object(Language))
#8 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/language/Message.php(865): Message->fetchMessage()
#9 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/language/Message.php(969): Message->toString('plain')
#10 /srv/mediawiki/tags/2019-08-15_08:46:28/extensions/Translate/TranslateHooks.php(527): Message->plain()
#11 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/Hooks.php(174): TranslateHooks::translateMessageDocumentationLanguage(Array, 'yua')
#12 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/Hooks.php(202): Hooks::callHook('LanguageGetTran...', Array, Array, NULL)
#13 /srv/mediawiki/tags/2019-08-15_08:46:28/languages/Language.php(880): Hooks::run('LanguageGetTran...', Array)
#14 /srv/mediawiki/tags/2019-08-15_08:46:28/languages/Language.php(849): Language::fetchLanguageNamesUncached('yua', 'all')
#15 /srv/mediawiki/tags/2019-08-15_08:46:28/languages/Language.php(943): Language::fetchLanguageNames('yua', 'all')
#16 /srv/mediawiki/tags/2019-08-15_08:46:28/languages/Language.php(435): Language::fetchLanguageName('yua', 'yua')
#17 /srv/mediawiki/tags/2019-08-15_08:46:28/extensions/Translate/specials/SpecialTranslations.php(245): Language::isKnownLanguageTag('yua')
#18 /srv/mediawiki/tags/2019-08-15_08:46:28/extensions/Translate/specials/SpecialTranslations.php(78): SpecialTranslations->showTranslations(Object(Title))
#19 /srv/mediawiki/tags/2019-08-15_08:46:28/includes/specialpage/SpecialPage.php(571): SpecialTranslations->execute('')

Need to investigate and see if this is caused due to an upstream issue / change

Event Timeline

Coming from the same line: PHP Warning: Invalid argument supplied for foreach()

This error can only happen when $wgAdaptiveMessageCache = true;:

458                 $mostused = []; // list of "<cased message key>/<code>"
459                 if ( $wgAdaptiveMessageCache && $code !== $wgLanguageCode ) {
460                         if ( !$this->cache->has( $wgLanguageCode ) ) {
461                                 $this->load( $wgLanguageCode );
462                         }
463                         $mostused = array_keys( $this->cache->get( $wgLanguageCode ) );
464                         foreach ( $mostused as $key => $value ) {
465                                 $mostused[$key] = "$value/$code";
466                         }
467                 }

Somehow this only seem to happen for unusual codes like yua, nog, pt-pt, prs, wls, kip. Somehow this feels similar to T208897#5373846.

Krinkle triaged this task as Medium priority.Sep 4 2019, 5:43 PM
MessageCache.php
if ( !$this->cache->has( $wgLanguageCode ) ) {
        $this->load( $wgLanguageCode );
}
$mostused = array_keys( $this->cache->get( $wgLanguageCode ) );
foreach ( $mostused as $key => $value ) {

For $this->cache->get(…) to give null to array_keys(), I tried to chase the following possibilities:

  • Does $this->cache allow storing of null?
    • Yes, it is set to MapCacheLRU where the set method allows any value to be set, including false and null. It uses array_key_exists to determine existence and has no illegal values. The getWithSetCallback does have an illegal value (it rejects boolean false from being set). At retrieval time, MapCacheLRU::get also allows specifying what the return value should be in case of absence, which defaults to null.
  • Does MessageCache ever call $this->cache->set($key, $val) where $val is null?
    • No, from what I can tell all the call sites have strong guarantees about it being an array.
  • This means the only way MapCacheLRU::get() can return null here is when the key has not been set. In other words, it returns null due to that being the default return value. And thus we can assume MapCacheLRU::has() would return false for the same key at that point.
  • Why do we assume it has been set?
    • The code right above it checks MapCacheLRU::has() and if false, calls MessageCache::load() with the expectation it will call $this->cache->set(…, …).
  • In what circumstances can it return without that having happened?
    • The MessageCache::load method has three return paths:
      • Early return for loadedLanguages already set, which I'm pretty sure means $this->cache->set has already happened as well. Task T208897 was about that sometimes not being the case, which we fixed.
      • Early return for MessageCache::mDisable == true. Possible?
      • Final return after $this->cache->set() has been done.

So my only guess would be that maybe MessageCache was disabled here. But that seems unlikely?

With regards to mDisable being true:

  • $wgUseDatabaseMessages is certainly true, so mDisable should not be set true in the constructor line 155. I could only find one place where MessageCache is constructed, in service wiring.
  • If loading fails for some reason, it might be disabled on line 356. If this is the case, it should be apparent from MessageCacheError log channel. I can't find anything in Logstash, so this does not seem to be the case in production?? In translatewiki.net, we don't have logging for that channel. I'll enable it.
  • Something could also call MessageCache::disable, but as non-static method it is hard to search in code search.

(Keeping as "Blocked" until twn has seen the error again with MessageCacheError enabled and confirmed whether it is the root cause or not.)

I enabled MessageCacheError logging on Mon Sep 9 11:02:37 2019 +0200. There is nothing in the logs. This error last appeared [2019-09-11 15:13:17]. I double checked that I didn't misconfigure anything. Maybe I should add logging if MessageCache::disable is getting called.

Good idea! That'd be great and rule this out once and for all.

There were a couple of instances of [2019-09-12 06:38:34] MessageCacheError.INFO: MessageCache::load: Failed to load hr {"private":false} [] but it doesn't seem to explain these errors. Also no callers on enable/disable.

I added some additional debugging:

diff --git a/includes/cache/MessageCache.php b/includes/cache/MessageCache.php
index 6272723..7d0f51a 100644
--- a/includes/cache/MessageCache.php
+++ b/includes/cache/MessageCache.php
@@ -454,9 +454,17 @@ class MessageCache {
 
                $mostused = []; // list of "<cased message key>/<code>"
                if ( $wgAdaptiveMessageCache && $code !== $wgLanguageCode ) {
-                       if ( !$this->cache->has( $wgLanguageCode ) ) {
-                               $this->load( $wgLanguageCode );
+                       $has = $this->cache->has( $wgLanguageCode );
+                       if ( !$has ) {
+                               $loaded = $this->load( $wgLanguageCode );
                        }
+
+                       $get = $this->cache->get( $wgLanguageCode );
+                       if ( !is_array( $get ) ) {
+                               $keys = $this->cache->getAllKeys();
+                               wfDebugLog( 'MessageCacheError', json_encode( [ $has, $loaded, $keys, $code, $wgLanguageCode ] ) );
+                       }
+
                        $mostused = array_keys( $this->cache->get( $wgLanguageCode ) );
                        foreach ( $mostused as $key => $value ) {
                                $mostused[$key] = "$value/$code";

The output is:

[2019-09-12 09:26:14] MessageCacheError.INFO: [false,true,["brx","cak","cnh","cnr-latn","cop"],"dag","en"] {"private":false} []
[2019-09-12 09:26:15] MessageCacheError.INFO: [false,true,["cak","cnh","cnr-latn","cop","dag"],"esu","en"] {"private":false} []
[2019-09-12 09:26:16] MessageCacheError.INFO: [false,true,["ksw","lag","lkt","lld","mfe"],"mic","en"] {"private":false} []
[2019-09-12 09:26:17] MessageCacheError.INFO: [false,true,["lkt","lld","mfe","mic","mui"],"nog","en"] {"private":false} []
[2019-09-12 09:26:18] MessageCacheError.INFO: [false,true,["mic","mui","nog","osi","ovd"],"pbb","en"] {"private":false} []
[2019-09-12 09:26:19] MessageCacheError.INFO: [false,true,["osi","ovd","pbb","ppl","prs"],"pt-pt","en"] {"private":false} []
[2019-09-12 09:26:20] MessageCacheError.INFO: [false,true,["ryu","saz","sly","sxu","trv"],"ttt","en"] {"private":false} []
[2019-09-12 09:26:21] MessageCacheError.INFO: [false,true,["sly","sxu","trv","ttt","tzl"],"wls","en"] {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading brx... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading cak... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading cnh... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading cnr-latn... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading cop... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:14] MessageCache.INFO: MessageCache::load: Loading zh-hans... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:15] MessageCache.INFO: MessageCache::load: Loading sr-ec... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:15] MessageCache.INFO: MessageCache::load: Loading dag... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:15] MessageCache.INFO: MessageCache::load: Loading en-gb... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:15] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:15] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading esu... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading fil... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading fon... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading frs... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading gaa... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading gcf... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading guc... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading hoc... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading hsn... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading jje... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading kea... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading kip... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading kjh... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading ksw... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading lag... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading lkt... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading lld... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading mfe... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading zh-cn... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:16] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:17] MessageCache.INFO: MessageCache::load: Loading bg... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:17] MessageCache.INFO: MessageCache::load: Loading bg... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:17] MessageCache.INFO: MessageCache::load: Loading mic... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:17] MessageCache.INFO: MessageCache::load: Loading mui... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:17] MessageCache.INFO: MessageCache::load: Loading kri... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading zh-hans... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading nog... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading osi... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading ovd... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading zh-cn... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:18] MessageCache.INFO: MessageCache::load: Loading zh-hans... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:19] MessageCache.INFO: MessageCache::load: Loading koi... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:19] MessageCache.INFO: MessageCache::load: Loading pbb... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:19] MessageCache.INFO: MessageCache::load: Loading ppl... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:19] MessageCache.INFO: MessageCache::load: Loading prs... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading en-gb... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading pt-pt... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading qwh... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading rej... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading rmf... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading rtm... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading ryu... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading saz... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading sly... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading sxu... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading trv... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:20] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading zh-cn... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading en... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading zh-hans... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading gl... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading ttt... local cache is empty, global cache is empty, loading from database {"private":false} []
[2019-09-12 09:26:21] MessageCache.INFO: MessageCache::load: Loading tzl... local cache is empty, got from global cache {"private":false} []
[2019-09-12 09:26:22] MessageCache.INFO: MessageCache::load: Loading wls... local cache is empty, global cache is empty, loading from database {"private":false} []

So in all these cases, the cache is initially not present, and I assume en has fallen out of cache, loading en (recursive call) claims success, but cache->get fails. Also all these codes are such that they are defined in our wgExtraLanguageNames and are likely not to have any translations.

@Krinkle Umm, can it just be as simple as en falling out of $this->cache due to LRU mechanism, and $this->loadedLanguages['en'] still being true, unaware of this fact. This is likely to happen if there are a lot of cache misses, because MapCacheLRU::has does not ping. If it called load unconditionally, it would continuously ping and keep en in the cache.

Other thing is that MessageCache::load could actually check whether the code is present in $this->cache. To me it seems $this->loadedLanguages is completely redundant with that.

@Nikerabbit We can't use $this->cache instead of $this->loadedLanguages because the process cache may contain partial values that got there without a proper loading. See T208897#5373846 for more about that, which was a different fatal error.

But yeah, we need to figure out a way to keep track of this without being surprised by LRU.

Can we put a special key on the cache value itself when it is populated by full cache load? If it is not present when we check the cache, then we know we only have partial value and need to (re)load?

Yes, I believe that would work :)

Change 539215 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] MessageCache: Replace internal loadedLanguages array with special cache key

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

Krinkle moved this task from Blocked (old) to Inbox, needs triage on the Performance-Team board.

Might need follow-up if something comes up in Aaron's CR.

Change 539215 merged by jenkins-bot:
[mediawiki/core@master] MessageCache: Replace internal loadedLanguages array with special cache key

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

Krinkle claimed this task.