Page MenuHomePhabricator
Create Task
Maniphest T304515

PHP Warning: Cannot use a scalar value as an array
Closed, ResolvedPublic
Actions

Description

I've seen this now on two builds for GrowthExperiments. The error is triggered during QUnit test runs, as far as I can tell, given that the relevant title is Special:JavaScriptTest/BadTitle

Example patch:

Example log:

00:19:30.166 mw-error.log:2022-03-23 14:09:57 831ffdec8904 wikidb: [30096c7e91d3a627fee2b508] /index.php?title=Special:Badtitle/JavaScriptTest   PHP Warning: Cannot use a scalar value as an array
00:19:30.166 mw-error.log:#0 /workspace/src/includes/cache/localisation/LCStoreStaticArray.php(60): MWExceptionHandler::handleError(integer, string, string, integer, array)
00:19:30.166 mw-error.log:#1 /workspace/src/includes/cache/localisation/LocalisationCache.php(1051): LCStoreStaticArray->set(string, string)
00:19:30.166 mw-error.log:#2 /workspace/src/includes/cache/localisation/LocalisationCache.php(496): LocalisationCache->recache(string)
00:19:30.166 mw-error.log:#3 /workspace/src/includes/cache/localisation/LocalisationCache.php(370): LocalisationCache->initLanguage(string)
00:19:30.166 mw-error.log:#4 /workspace/src/includes/cache/localisation/LocalisationCache.php(311): LocalisationCache->loadItem(string, string)
00:19:30.166 mw-error.log:#5 /workspace/src/includes/language/LanguageFallback.php(106): LocalisationCache->getItem(string, string)
00:19:30.166 mw-error.log:#6 /workspace/src/includes/language/LanguageFactory.php(167): MediaWiki\Languages\LanguageFallback->getAll(string)
00:19:30.166 mw-error.log:#7 /workspace/src/includes/language/LanguageFactory.php(126): MediaWiki\Languages\LanguageFactory->newFromCode(string)
00:19:30.166 mw-error.log:#8 /workspace/src/includes/libs/MapCacheLRU.php(274): MediaWiki\Languages\LanguageFactory->MediaWiki\Languages\{closure}()
00:19:30.166 mw-error.log:#9 /workspace/src/includes/language/LanguageFactory.php(127): MapCacheLRU->getWithSetCallback(string, Closure)
00:19:30.166 mw-error.log:#10 /workspace/src/includes/language/LanguageFactory.php(208): MediaWiki\Languages\LanguageFactory->getLanguage(string)
00:19:30.166 mw-error.log:#11 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(140): MediaWiki\Languages\LanguageFactory->getParentLanguage(string)
00:19:30.166 mw-error.log:#12 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(180): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsToChain(LanguageEn, array, array)
00:19:30.166 mw-error.log:#13 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(211): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsAndFallbacksToChain(LanguageEn, array, array)
00:19:30.166 mw-error.log:#14 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(78): Wikibase\Lib\LanguageFallbackChainFactory->buildFromLanguage(LanguageEn)
00:19:30.166 mw-error.log:#15 /workspace/src/extensions/Wikibase/lib/includes/Store/LanguageFallbackLabelDescriptionLookupFactory.php(70): Wikibase\Lib\LanguageFallbackChainFactory->newFromLanguage(LanguageEn)
00:19:30.166 mw-error.log:#16 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(845): Wikibase\Lib\Store\LanguageFallbackLabelDescriptionLookupFactory->newLabelDescriptionLookup(LanguageEn)
00:19:30.166 mw-error.log:#17 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
00:19:30.166 mw-error.log:#18 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
00:19:30.166 mw-error.log:#19 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
00:19:30.166 mw-error.log:#20 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
00:19:30.166 mw-error.log:#21 /workspace/src/extensions/Wikibase/client/includes/WikibaseClient.php(326): Wikimedia\Services\ServiceContainer->get(string)
00:19:30.166 mw-error.log:#22 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(588): Wikibase\Client\WikibaseClient::getSidebarLinkBadgeDisplay(MediaWiki\MediaWikiServices)
00:19:30.166 mw-error.log:#23 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
00:19:30.166 mw-error.log:#24 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
00:19:30.166 mw-error.log:#25 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
00:19:30.166 mw-error.log:#26 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
00:19:30.166 mw-error.log:#27 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(211): Wikimedia\Services\ServiceContainer->get(string)
00:19:30.166 mw-error.log:#28 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(152): Wikimedia\ObjectFactory\ObjectFactory::getObjectFromSpec(array, array)
00:19:30.166 mw-error.log:#29 /workspace/src/includes/HookContainer/HookContainer.php(473): Wikimedia\ObjectFactory\ObjectFactory->createObject(array)
00:19:30.166 mw-error.log:#30 /workspace/src/includes/HookContainer/HookContainer.php(156): MediaWiki\HookContainer\HookContainer->getHandlers(string, array)
00:19:30.166 mw-error.log:#31 /workspace/src/includes/HookContainer/HookRunner.php(3372): MediaWiki\HookContainer\HookContainer->run(string, array, array)
00:19:30.166 mw-error.log:#32 /workspace/src/includes/skins/Skin.php(1585): MediaWiki\HookContainer\HookRunner->onSidebarBeforeOutput(Vector\SkinVector, array)
00:19:30.166 mw-error.log:#33 /workspace/src/includes/skins/SkinTemplate.php(784): Skin->buildSidebar()
00:19:30.166 mw-error.log:#34 /workspace/src/includes/skins/SkinTemplate.php(202): SkinTemplate->getPortletsTemplateData()
00:19:30.167 mw-error.log:#35 /workspace/src/includes/skins/SkinMustache.php(81): SkinTemplate->getTemplateData()
00:19:30.167 mw-error.log:#36 /workspace/src/skins/Vector/includes/SkinVector.php(564): SkinMustache->getTemplateData()
00:19:30.167 mw-error.log:#37 /workspace/src/includes/skins/SkinMustache.php(58): Vector\SkinVector->getTemplateData()
00:19:30.167 mw-error.log:#38 /workspace/src/skins/Vector/includes/SkinVector.php(455): SkinMustache->generateHTML()
00:19:30.167 mw-error.log:#39 /workspace/src/includes/skins/SkinTemplate.php(150): Vector\SkinVector->generateHTML()
00:19:30.167 mw-error.log:#40 /workspace/src/includes/OutputPage.php(2808): SkinTemplate->outputPage()
00:19:30.167 mw-error.log:#41 /workspace/src/includes/MediaWiki.php(925): OutputPage->output(boolean)
00:19:30.167 mw-error.log:#42 /workspace/src/includes/MediaWiki.php(938): MediaWiki::{closure}()
00:19:30.167 mw-error.log:#43 /workspace/src/includes/MediaWiki.php(565): MediaWiki->main()
00:19:30.167 mw-error.log:#44 /workspace/src/index.php(53): MediaWiki->run()
00:19:30.167 mw-error.log:#45 /workspace/src/index.php(46): wfIndexMain()
00:19:30.167 mw-error.log:#46 {main}
`

Details

SubjectRepoBranchLines +/-
LCStoreStaticArray: atomically replace the cache filemediawiki/coreREL1_35+5 -1
LCStoreStaticArray: atomically replace the cache filemediawiki/coreREL1_38+5 -1
LCStoreStaticArray: atomically replace the cache filemediawiki/coreREL1_39+5 -1
LCStoreStaticArray: atomically replace the cache filemediawiki/coremaster+5 -1
tests: Add missing teardown for setOptionsForTest()mediawiki/extensions/EventLoggingmaster+7 -2
Customize query in gerrit

Related Objects

Event Timeline

kostajh created this task.Mar 23 2022, 2:30 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 23 2022, 2:30 PM
kostajh renamed this task from Cannot use scalar value as array to PHP Warning: Cannot use a scalar value as an array.Mar 23 2022, 2:31 PM
kostajh updated the task description. (Show Details)
kostajh added a project: MediaWiki-extensions-WikibaseClient.

Tentatively tagging WikibaseClient, since it's seen in the stack trace, though I am not sure if it is directly involved in this error.

Maintenance_bot added a project: Wikidata.Mar 23 2022, 2:45 PM
kostajh triaged this task as Unbreak Now! priority.Mar 23 2022, 3:10 PM
kostajh added a project: GrowthExperiments.
kostajh added a subscriber: hashar.

Blocking merges to GrowthExperiments, not sure if other extensions are affected.

Restricted Application added a project: Growth-Team. · View Herald TranscriptMar 23 2022, 3:10 PM
Krinkle added a comment.Mar 23 2022, 6:50 PM

This seems to sporadically come up and is limited to the shared WMF-extension gate job, when Wikibase is installed.

P22994 (An Untitled Masterwork)
1# https://gerrit.wikimedia.org/r/c/mediawiki/core/+/772825/
2# https://integration.wikimedia.org/ci/job/wmf-quibble-core-vendor-mysql-php72-docker/75920/
3
4$ cat mw-error.log | fgrep 2022-03 | cut -d' ' -f6- | sort | uniq -c
5 197516 /index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: Cannot use a scalar value as an array
6 30 /index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: array_key_exists() expects parameter 2 to be array, integer given
7 11 /index.php?title=Special:Badtitle/JavaScriptTest TypeError: Argument 1 passed to Wikimedia\StaticArrayWriter::create() must be of the type array, integer given, called in /workspace/src/includes/cache/localisation/LCStoreStaticArray.php on line 143

There appears to be a situation in which something is causing LocalisastionCache to initialise a new uncached language with a dataset of int(1) (instead of an array of message keys and values). In that situation, we see the following chain:

  • ..
  • Wikibase LanguageFallbackChainFactory
  • ..
  • LanguageFactory->newFromCode
  • ..
  • LocalisationCache->recache
    • LCStoreStaticArray->set(string, string) - This causes PHP Warning: Cannot use a scalar value as an array because $this->data is an integer instead of an array.
    • LCStoreStaticArray::finishWrite - This causes the fatal TypeError: Argument 1 passed to Wikimedia\StaticArrayWriter::create().

It's not clear to me how $this->data can be an integer there. It is explicitly set to an array in the constructor, and we then read cache/l10n/:lang.php if it exists, which presumably either won't exist or if we just generated it it would be written as array and up-to-date and not needing to be written to. The fatal error also clearly indicates that the code doesn't even allow itself to create that file as a non-array, so it's not clear how that file can end up as an integer.

kostajh added a comment.Mar 23 2022, 7:03 PM
In T304515#7801064, @Krinkle wrote:

This seems to sporadically come up and is limited to the shared WMF-extension gate job, when Wikibase is installed.

P22994 (An Untitled Masterwork)
1# https://gerrit.wikimedia.org/r/c/mediawiki/core/+/772825/
2# https://integration.wikimedia.org/ci/job/wmf-quibble-core-vendor-mysql-php72-docker/75920/
3
4$ cat mw-error.log | fgrep 2022-03 | cut -d' ' -f6- | sort | uniq -c
5 197516 /index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: Cannot use a scalar value as an array
6 30 /index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: array_key_exists() expects parameter 2 to be array, integer given
7 11 /index.php?title=Special:Badtitle/JavaScriptTest TypeError: Argument 1 passed to Wikimedia\StaticArrayWriter::create() must be of the type array, integer given, called in /workspace/src/includes/cache/localisation/LCStoreStaticArray.php on line 143

There appears to be a situation in which something is causing LocalisastionCache to initialise a new uncached language with a dataset of int(1) (instead of an array of message keys and values). In that situation, we see the following chain:

  • ..
  • Wikibase LanguageFallbackChainFactory
  • ..
  • LanguageFactory->newFromCode
  • ..
  • LocalisationCache->recache
    • LCStoreStaticArray->set(string, string) - This causes PHP Warning: Cannot use a scalar value as an array because $this->data is an integer instead of an array.
    • LCStoreStaticArray::finishWrite - This causes the fatal TypeError: Argument 1 passed to Wikimedia\StaticArrayWriter::create().

It's not clear to me how $this->data can be an integer there. It is explicitly set to an array in the constructor, and we then read cache/l10n/:lang.php if it exists, which presumably either won't exist or if we just generated it it would be written as array and up-to-date and not needing to be written to. The fatal error also clearly indicates that the code doesn't even allow itself to create that file as a non-array, so it's not clear how that file can end up as an integer.

Thanks for that context. I can't find it now, but there was another stack trace with a different error, where it looks like the PHP file for the localisation cache was corrupted; it was missing a closing ' somewhere perhaps. I'll see if I can dig it up.

kostajh added a comment.Mar 23 2022, 7:58 PM
In T304515#7801115, @kostajh wrote:

Thanks for that context. I can't find it now, but there was another stack trace with a different error, where it looks like the PHP file for the localisation cache was corrupted; it was missing a closing ' somewhere perhaps. I'll see if I can dig it up.

Found it: https://integration.wikimedia.org/ci/job/wmf-quibble-vendor-mysql-php72-docker/93336/console

00:13:23.534 mw-error.log:2022-03-23 14:33:16 8b3a3186d2ea wikidb: [da4a66e39ff387f350450fda] /index.php?title=Special:Badtitle/JavaScriptTest   ParseError: syntax error, unexpected ''apihel' (T_ENCAPSED_AND_WHITESPACE)
00:13:23.535 mw-error.log:#0 /workspace/src/includes/cache/localisation/LocalisationCache.php(448): LCStoreStaticArray->get(string, string)
00:13:23.535 mw-error.log:#1 /workspace/src/includes/cache/localisation/LocalisationCache.php(494): LocalisationCache->isExpired(string)
00:13:23.535 mw-error.log:#2 /workspace/src/includes/cache/localisation/LocalisationCache.php(370): LocalisationCache->initLanguage(string)
00:13:23.535 mw-error.log:#3 /workspace/src/includes/cache/localisation/LocalisationCache.php(311): LocalisationCache->loadItem(string, string)
00:13:23.535 mw-error.log:#4 /workspace/src/includes/language/LanguageFallback.php(106): LocalisationCache->getItem(string, string)
00:13:23.535 mw-error.log:#5 /workspace/src/includes/language/LanguageFactory.php(167): MediaWiki\Languages\LanguageFallback->getAll(string)
00:13:23.535 mw-error.log:#6 /workspace/src/includes/language/LanguageFactory.php(126): MediaWiki\Languages\LanguageFactory->newFromCode(string)
00:13:23.535 mw-error.log:#7 /workspace/src/includes/libs/MapCacheLRU.php(274): MediaWiki\Languages\LanguageFactory->MediaWiki\Languages\{closure}()
00:13:23.535 mw-error.log:#8 /workspace/src/includes/language/LanguageFactory.php(127): MapCacheLRU->getWithSetCallback(string, Closure)
00:13:23.535 mw-error.log:#9 /workspace/src/includes/language/LanguageFactory.php(208): MediaWiki\Languages\LanguageFactory->getLanguage(string)
00:13:23.535 mw-error.log:#10 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(140): MediaWiki\Languages\LanguageFactory->getParentLanguage(string)
00:13:23.535 mw-error.log:#11 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(180): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsToChain(LanguageEn, array, array)
00:13:23.535 mw-error.log:#12 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(211): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsAndFallbacksToChain(LanguageEn, array, array)
00:13:23.535 mw-error.log:#13 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(78): Wikibase\Lib\LanguageFallbackChainFactory->buildFromLanguage(LanguageEn)
00:13:23.535 mw-error.log:#14 /workspace/src/extensions/Wikibase/lib/includes/Store/LanguageFallbackLabelDescriptionLookupFactory.php(70): Wikibase\Lib\LanguageFallbackChainFactory->newFromLanguage(LanguageEn)
00:13:23.535 mw-error.log:#15 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(845): Wikibase\Lib\Store\LanguageFallbackLabelDescriptionLookupFactory->newLabelDescriptionLookup(LanguageEn)
00:13:23.535 mw-error.log:#16 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
00:13:23.535 mw-error.log:#17 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
00:13:23.535 mw-error.log:#18 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
00:13:23.535 mw-error.log:#19 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
00:13:23.535 mw-error.log:#20 /workspace/src/extensions/Wikibase/client/includes/WikibaseClient.php(326): Wikimedia\Services\ServiceContainer->get(string)
00:13:23.535 mw-error.log:#21 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(588): Wikibase\Client\WikibaseClient::getSidebarLinkBadgeDisplay(MediaWiki\MediaWikiServices)
00:13:23.535 mw-error.log:#22 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
00:13:23.535 mw-error.log:#23 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
00:13:23.535 mw-error.log:#24 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
00:13:23.535 mw-error.log:#25 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
00:13:23.535 mw-error.log:#26 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(211): Wikimedia\Services\ServiceContainer->get(string)
00:13:23.535 mw-error.log:#27 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(152): Wikimedia\ObjectFactory\ObjectFactory::getObjectFromSpec(array, array)
00:13:23.535 mw-error.log:#28 /workspace/src/includes/HookContainer/HookContainer.php(473): Wikimedia\ObjectFactory\ObjectFactory->createObject(array)
00:13:23.535 mw-error.log:#29 /workspace/src/includes/HookContainer/HookContainer.php(156): MediaWiki\HookContainer\HookContainer->getHandlers(string, array)
00:13:23.535 mw-error.log:#30 /workspace/src/includes/HookContainer/HookRunner.php(3372): MediaWiki\HookContainer\HookContainer->run(string, array, array)
00:13:23.535 mw-error.log:#31 /workspace/src/includes/skins/Skin.php(1585): MediaWiki\HookContainer\HookRunner->onSidebarBeforeOutput(Vector\SkinVector, array)
00:13:23.535 mw-error.log:#32 /workspace/src/includes/skins/SkinTemplate.php(784): Skin->buildSidebar()
00:13:23.535 mw-error.log:#33 /workspace/src/includes/skins/SkinTemplate.php(202): SkinTemplate->getPortletsTemplateData()
00:13:23.535 mw-error.log:#34 /workspace/src/includes/skins/SkinMustache.php(81): SkinTemplate->getTemplateData()
00:13:23.535 mw-error.log:#35 /workspace/src/skins/Vector/includes/SkinVector.php(564): SkinMustache->getTemplateData()
00:13:23.535 mw-error.log:#36 /workspace/src/includes/skins/SkinMustache.php(58): Vector\SkinVector->getTemplateData()
00:13:23.535 mw-error.log:#37 /workspace/src/skins/Vector/includes/SkinVector.php(455): SkinMustache->generateHTML()
00:13:23.536 mw-error.log:#38 /workspace/src/includes/skins/SkinTemplate.php(150): Vector\SkinVector->generateHTML()
00:13:23.536 mw-error.log:#39 /workspace/src/includes/OutputPage.php(2808): SkinTemplate->outputPage()
00:13:23.536 mw-error.log:#40 /workspace/src/includes/MediaWiki.php(925): OutputPage->output(boolean)
00:13:23.536 mw-error.log:#41 /workspace/src/includes/MediaWiki.php(938): MediaWiki::{closure}()
00:13:23.536 mw-error.log:#42 /workspace/src/includes/MediaWiki.php(565): MediaWiki->main()
00:13:23.536 mw-error.log:#43 /workspace/src/index.php(53): MediaWiki->run()
00:13:23.536 mw-error.log:#44 /workspace/src/index.php(46): wfIndexMain()
00:13:23.536 mw-error.log:#45 {main}
kostajh mentioned this in T304560: Random test failures producing gigabytes of logs like "/index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: Cannot use a scalar value as an array".Mar 23 2022, 8:01 PM
RhinosF1 subscribed.Mar 23 2022, 8:04 PM
matmarex merged a task: T304560: Random test failures producing gigabytes of logs like "/index.php?title=Special:Badtitle/JavaScriptTest PHP Warning: Cannot use a scalar value as an array".Mar 23 2022, 8:06 PM
matmarex subscribed.
matmarex added a comment.Mar 23 2022, 8:10 PM

The issue doesn't seem related to GrowthExperiments, I've seen the same failure for mediawiki/core changes.

Also, the error results in huge amounts of output (1.2 GB is the most I've seen), which probably isn't great for Jenkins's well-being.

kostajh removed projects: GrowthExperiments, Growth-Team.Mar 23 2022, 8:13 PM
In T304515#7801441, @matmarex wrote:

The issue doesn't seem related to GrowthExperiments, I've seen the same failure for mediawiki/core changes.

OK, untagging Growth then.

matmarex added a comment.Mar 23 2022, 8:23 PM
In T304515#7801362, @kostajh wrote:
In T304515#7801115, @kostajh wrote:

Thanks for that context. I can't find it now, but there was another stack trace with a different error, where it looks like the PHP file for the localisation cache was corrupted; it was missing a closing ' somewhere perhaps. I'll see if I can dig it up.

Found it: https://integration.wikimedia.org/ci/job/wmf-quibble-vendor-mysql-php72-docker/93336/console

I've just had this happen too: https://integration.wikimedia.org/ci/job/wmf-quibble-core-vendor-mysql-php72-docker/75983/console

20:40:51 mw-error.log:2022-03-23 19:33:17 9566e3dfbcd6 wikidb: [35b927874603ae41d4d4458d] /index.php?title=Special:Badtitle/JavaScriptTest   ParseError: syntax error, unexpected ''messages:cx-sx-publisher-publ' (T_ENCAPSED_AND_WHITESPACE), expecting ']'
20:40:51 mw-error.log:2022-03-23 19:33:17 9566e3dfbcd6 wikidb: [a1814ed5ff46ab6fc6cd8a62] /index.php?title=Special:Badtitle/JavaScriptTest   ParseError: syntax error, unexpected ''<div class="hlist plainli' (T_ENCAPSED_AND_WHITESPACE)
Lucas_Werkmeister_WMDE subscribed.Mar 24 2022, 9:52 AM
Michael subscribed.Mar 24 2022, 11:31 AM
• toan subscribed.Mar 24 2022, 11:52 AM

Has this happened recently? Last failure I can see was 13 hours ago, and it seemed to only happen at random?

kostajh lowered the priority of this task from Unbreak Now! to Needs Triage.EditedMar 24 2022, 1:34 PM

Is it possibly an instance of T245183: PHP7 corruption reports in 2020-2022 (Call on wrong object, etc.)?

Resetting the priority, as merges are going through again now.

Krinkle added a project: VisualEditor.EditedMar 24 2022, 5:48 PM
Krinkle added a subscriber: Esanders.

The current assumption around how php-opcache gets corrupted in prod is that there is a race condition when the main php-fpm process detects that opcache is full (e.g. due to files having changed since it never deletes old versions, e.g. after a new branch gets added to a server, and unused two week old code paths are still in the opcache). When it is full, it does a full reset and starts populating again which with our traffic seems to sometimes trigger a race where it corrupts itself. Our assumption so far has been that it is not possible to trigger this when you have unchanging code and are simply compiling it, like CI does.

Having said that, there are two possibilities I see. 1) Our assumption is incorrect and the recent enablement of of Apache in CI has exposed us to opcache corruption. Or 2) Our code in the shared gate has reached the size that no longer fits in the default opcache size and thus may sometimes be getting too big to not consistently fit but forced to evict stuff during the browser tests and then immediately re-compile the same stuff again and likely reach the fullness again.

While I don't have a root cause answer to this error. I do know the immediate cause of it. It seems these errors are only happening on POST requests to Special:Badtitle, which is certainly an odd thing to be seeing. Badtitle is the value of wgPageName during the QUnit tests (I modified it in change 772502 to confirm this suspicion and make it easier to detect in the future).

I haven't yet figured out what's making the requests, but I have found what's causing the referer to be Badtitle. It seems the ve.init.* tests are changing the address bar to Badtitle. Something similar came up in change 500819 for T89434, but that was since fixed by @Esanders with change 768041 and change 768046. I'm guessing something here is still causing that to be triggered (and more importantly, and if intentional: not torn down afterward).

This also has the side-effect of breaking the QUnit UI when VE is installed locally, as it will lead to Badtitle after form submission.

Lucas_Werkmeister_WMDE added a comment.Mar 28 2022, 2:06 PM
In T304515#7802954, @toan wrote:

Has this happened recently? Last failure I can see was 13 hours ago, and it seemed to only happen at random?

I’ve just had it happen again in wmf-quibble-vendor-mysql-php72-docker #93724 (though that was the first time I saw it since Thursday).

Krinkle added a comment.Mar 29 2022, 8:07 PM
In T304515#7804508, @Krinkle wrote:

[…]
While I don't have a root cause answer to this error. I do know the immediate cause of it. It seems these errors are only happening on POST requests to Special:Badtitle, […].

I haven't yet figured out what's making the requests, but I have found what's causing the referer to be Badtitle. It seems the ve.init.* tests are changing the address bar to Badtitle. […] This also has the side-effect of breaking the QUnit UI when VE is installed.

I've managed to observe the POST requests locally by enabling (most) of the CI-gated extensions locally. These are coming from GrowthExperiments' unit tests, which are calling to sendBeacon() via EventLogging.

The reason the requests were seen by CI without an event payload (neither in URL nor in body) will become apparent in a moment.

POST /wiki/Special:JavaScriptTest#?%7B%22event%22%3A%7B%22newcomer_task_token%22%3A%221234%22%2C%22task_type%22%3A%22copyedit%22%2C%22maintenance_templates%22%3A%5B%5D%2C%22revision_id%22%3A102%2C%22page_id%22%3A101%2C%22page_title%22%3A%22Some%20title%22%2C%22has_image%22%3Afalse%2C%22ordinal_position%22%3A100%7D%2C%22schema%22%3A%22NewcomerTask%22%2C%22webHost%22%3A%22mw.localhost%22%2C%22wiki%22%3A%22foowiki%22%2C%22revision%22%3A-1%7D;
POST /wiki/Special:JavaScriptTest#?%7B%22event%22%3A%7B%22newcomer_task_token%22%3A%221234%22%2C%22task_type%22%3A%22copyedit%22%2C%22maintenance_templates%22%3A%5B%5D%2C%22page_id%22%3A73%2C%22page_title%22%3A%22Some%20title%22%2C%22has_image%22%3Afalse%2C%22ordinal_position%22%3A0%7D%2C%22schema%22%3A%22NewcomerTask%22%2C%22webHost%22%3A%22mw.localhost%22%2C%22wiki%22%3A%22foowiki%22%2C%22revision%22%3A-1%7D;
POST /wiki/Special:JavaScriptTest#?%7B%22event%22%3A%7B%22message%22%3A%22Parse%20error%20at%20position%200%20in%20input%3A%20%5B%5BTampa%2C%20Florida%7C%5D%5D%22%2C%22url%22%3A%22jqueryMsg%3A%2F%2Fpipe-trick%22%2C%22line%22%3A0%2C%22column%22%3A0%2C%22flowId%22%3A%2216485826419007%22%2C%22flowPosition%22%3A1%7D%2C%22schema%22%3A%22UploadWizardExceptionFlowEvent%22%2C%22webHost%22%3A%22wiki.xyz%22%2C%22wiki%22%3A%22foowiki%22%2C%22revision%22%3A-1%7D;
..
POST /wiki/Special:Badtitle/JavaScriptTest#?%7B%22event%22%3A%7B%22message%22%3A%22Parse%20error%20at%20position%200%20in%20input%3A%20%5B%5B%5D%5D%22%2C%22url%22%3A%22jqueryMsg%3A%2F%2Fempty-link%22%2C%22line%22%3A0%2C%22column%22%3A0%2C%22flowId%22%3A%2216485832632794%22%2C%22flowPosition%22%3A3%7D%2C%22schema%22%3A%22UploadWizardExceptionFlowEvent%22%2C%22webHost%22%3A%22wiki.xyz%22%2C%22wiki%22%3A%22foowiki%22%2C%22revision%22%3A-1%7D; HTTP/1.1

Note how there is a hash # between the end of the path and the start of the would-be query string holding the event payload. This comes from ext.eventLogging/log.test.js#7 which fails to restore the state afterwards. This is my fault (change 583183), both for not restoring it but also more broadly as being not working as intended. See, I copied this from ext.eventLogging.debug.tests.js#77 for the original EventLogging service which used GET requests, and so by setting the base URI to a hash I accomplished two things: 1) The feature is now enabled for testing, and 2) It still doesn't go anywhere since navigations to hash are a no-op. Except, that's not true for AJAX requests. And even then, it most certainly isn't true for POST requests which will happen no matter what and the hash just gets ignored.

In summary:

  • In CI, we are seeing corruption that looks eerily familiar to the php-opcache corruption we see in prod (T245183).
  • I explained at T304515#7804508 that this is strange given we don't modify files. This might mean we just need to increase the size, or it might mean php-opcache is worse than we thought and can cause this race even during normal compiling of new files to opcache. If it's opcache related, then the immediate cause would be the switch from php-webserver to php-fpm with Apache. T285649
  • The secondary cause is the bombarding of the server with POST requests. These come from unit tests for GrowthExperiments and UploadWizard. These tests are not at fault as EventLogging is meant to be no-op by default.
  • The tertiary cause is that I broke EventLogging's tests.
  • The quaternary cause is that VisualEditor's tests are dirtying the address bar to Special:Badtitle, thus causing the storm of POST requests to excercise the full skin, lcoalisation and page rendering pipeline in all the parallel processes;' instead of the light Special:JavaScriptTest endpoint that runs relatively little code.
kostajh added a comment.Mar 30 2022, 7:50 PM
In T304515#7815997, @Krinkle wrote:
  • I explained at T304515#7804508 that this is strange given we don't modify files. This might mean we just need to increase the size, or it might mean php-opcache is worse than we thought and can cause this race even during normal compiling of new files to opcache. If it's opcache related, then the immediate cause would be the switch from php-webserver to php-fpm with Apache. T285649

GrowthExperiments is using a hack to get Parsoid working with VisualEditor in CI; we modify LocalSettings.php to require_once the GrowthExperiments.LocalSettings.php file, see https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/extensions/GrowthExperiments/+/refs/heads/master/tests/selenium/wdio.conf.js#45. And then we restart php-fpm. I don't know if that is related to this bug, but just wanted to note it here in case it is.

gerritbot added a comment.Mar 30 2022, 10:34 PM

Change 775401 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/extensions/EventLogging@master] tests: Add missing teardown for setOptionsForTest()

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

gerritbot added a project: Patch-For-Review.Mar 30 2022, 10:34 PM
gerritbot added a comment.Mar 31 2022, 5:07 PM

Change 775401 merged by jenkins-bot:

[mediawiki/extensions/EventLogging@master] tests: Add missing teardown for setOptionsForTest()

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

Maintenance_bot removed a project: Patch-For-Review.Mar 31 2022, 5:10 PM
ReleaseTaggerBot added a project: MW-1.39-notes (1.39.0-wmf.6; 2022-04-04).Mar 31 2022, 6:00 PM
Esanders unsubscribed.Apr 1 2022, 8:17 AM
kostajh added a comment.Apr 6 2022, 7:41 AM

Seen again in https://integration.wikimedia.org/ci/job/wmf-quibble-vendor-mysql-php72-docker/94745/console

09:38:08 mw-error.log:2022-04-06 07:28:40 ba9c06094630 wikidb: [836ae96dbb37c0bf76790a53] /index.php?title=Special:Badtitle/JavaScriptTest   ParseError: syntax error, unexpected end of file, expecting ']'
09:38:08 mw-error.log:#0 /workspace/src/includes/cache/localisation/LocalisationCache.php(1044): LCStoreStaticArray->startWrite(string)
09:38:08 mw-error.log:#1 /workspace/src/includes/cache/localisation/LocalisationCache.php(496): LocalisationCache->recache(string)
09:38:08 mw-error.log:#2 /workspace/src/includes/cache/localisation/LocalisationCache.php(370): LocalisationCache->initLanguage(string)
09:38:08 mw-error.log:#3 /workspace/src/includes/cache/localisation/LocalisationCache.php(311): LocalisationCache->loadItem(string, string)
09:38:08 mw-error.log:#4 /workspace/src/includes/language/LanguageFallback.php(106): LocalisationCache->getItem(string, string)
09:38:08 mw-error.log:#5 /workspace/src/includes/language/LanguageFactory.php(167): MediaWiki\Languages\LanguageFallback->getAll(string)
09:38:08 mw-error.log:#6 /workspace/src/includes/language/LanguageFactory.php(126): MediaWiki\Languages\LanguageFactory->newFromCode(string)
09:38:08 mw-error.log:#7 /workspace/src/includes/libs/MapCacheLRU.php(274): MediaWiki\Languages\LanguageFactory->MediaWiki\Languages\{closure}()
09:38:08 mw-error.log:#8 /workspace/src/includes/language/LanguageFactory.php(127): MapCacheLRU->getWithSetCallback(string, Closure)
09:38:08 mw-error.log:#9 /workspace/src/includes/language/LanguageFactory.php(208): MediaWiki\Languages\LanguageFactory->getLanguage(string)
09:38:08 mw-error.log:#10 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(140): MediaWiki\Languages\LanguageFactory->getParentLanguage(string)
09:38:08 mw-error.log:#11 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(180): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsToChain(LanguageEn, array, array)
09:38:08 mw-error.log:#12 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(211): Wikibase\Lib\LanguageFallbackChainFactory->addLanguageAndVariantsAndFallbacksToChain(LanguageEn, array, array)
09:38:08 mw-error.log:#13 /workspace/src/extensions/Wikibase/lib/includes/LanguageFallbackChainFactory.php(78): Wikibase\Lib\LanguageFallbackChainFactory->buildFromLanguage(LanguageEn)
09:38:08 mw-error.log:#14 /workspace/src/extensions/Wikibase/lib/includes/Store/LanguageFallbackLabelDescriptionLookupFactory.php(70): Wikibase\Lib\LanguageFallbackChainFactory->newFromLanguage(LanguageEn)
09:38:08 mw-error.log:#15 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(845): Wikibase\Lib\Store\LanguageFallbackLabelDescriptionLookupFactory->newLabelDescriptionLookup(LanguageEn)
09:38:08 mw-error.log:#16 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
09:38:08 mw-error.log:#17 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
09:38:08 mw-error.log:#18 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
09:38:08 mw-error.log:#19 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
09:38:08 mw-error.log:#20 /workspace/src/extensions/Wikibase/client/includes/WikibaseClient.php(326): Wikimedia\Services\ServiceContainer->get(string)
09:38:08 mw-error.log:#21 /workspace/src/extensions/Wikibase/client/WikibaseClient.ServiceWiring.php(588): Wikibase\Client\WikibaseClient::getSidebarLinkBadgeDisplay(MediaWiki\MediaWikiServices)
09:38:08 mw-error.log:#22 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(447): Wikimedia\Services\ServiceContainer->{closure}(MediaWiki\MediaWikiServices)
09:38:08 mw-error.log:#23 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(416): Wikimedia\Services\ServiceContainer->createService(string)
09:38:08 mw-error.log:#24 /workspace/src/includes/MediaWikiServices.php(294): Wikimedia\Services\ServiceContainer->getService(string)
09:38:08 mw-error.log:#25 /workspace/src/vendor/wikimedia/services/src/ServiceContainer.php(424): MediaWiki\MediaWikiServices->getService(string)
09:38:08 mw-error.log:#26 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(211): Wikimedia\Services\ServiceContainer->get(string)
09:38:08 mw-error.log:#27 /workspace/src/vendor/wikimedia/object-factory/src/ObjectFactory.php(152): Wikimedia\ObjectFactory\ObjectFactory::getObjectFromSpec(array, array)
09:38:08 mw-error.log:#28 /workspace/src/includes/HookContainer/HookContainer.php(473): Wikimedia\ObjectFactory\ObjectFactory->createObject(array)
09:38:08 mw-error.log:#29 /workspace/src/includes/HookContainer/HookContainer.php(156): MediaWiki\HookContainer\HookContainer->getHandlers(string, array)
09:38:08 mw-error.log:#30 /workspace/src/includes/HookContainer/HookRunner.php(3372): MediaWiki\HookContainer\HookContainer->run(string, array, array)
09:38:08 mw-error.log:#31 /workspace/src/includes/skins/Skin.php(1582): MediaWiki\HookContainer\HookRunner->onSidebarBeforeOutput(Vector\SkinVectorLegacy, array)
09:38:08 mw-error.log:#32 /workspace/src/includes/skins/SkinTemplate.php(784): Skin->buildSidebar()
09:38:08 mw-error.log:#33 /workspace/src/includes/skins/SkinTemplate.php(202): SkinTemplate->getPortletsTemplateData()
09:38:08 mw-error.log:#34 /workspace/src/includes/skins/SkinMustache.php(81): SkinTemplate->getTemplateData()
09:38:08 mw-error.log:#35 /workspace/src/skins/Vector/includes/SkinVector.php(499): SkinMustache->getTemplateData()
09:38:08 mw-error.log:#36 /workspace/src/includes/skins/SkinMustache.php(58): Vector\SkinVector->getTemplateData()
09:38:08 mw-error.log:#37 /workspace/src/includes/skins/SkinTemplate.php(150): SkinMustache->generateHTML()
09:38:08 mw-error.log:#38 /workspace/src/includes/OutputPage.php(2808): SkinTemplate->outputPage()
09:38:08 mw-error.log:#39 /workspace/src/includes/MediaWiki.php(925): OutputPage->output(boolean)
09:38:08 mw-error.log:#40 /workspace/src/includes/MediaWiki.php(938): MediaWiki::{closure}()
09:38:08 mw-error.log:#41 /workspace/src/includes/MediaWiki.php(565): MediaWiki->main()
09:38:08 mw-error.log:#42 /workspace/src/index.php(53): MediaWiki->run()
09:38:08 mw-error.log:#43 /workspace/src/index.php(46): wfIndexMain()
09:38:08 mw-error.log:#44 {main}
hashar unsubscribed.Apr 20 2022, 12:40 PM
• ppelberg moved this task from To Triage to Triaged on the VisualEditor board.Apr 21 2022, 3:47 PM
tstarling subscribed.Dec 1 2022, 2:09 AM

I noticed such a parse error on https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php74-docker/9834/ :

2022-12-01 00:18:47 ff4e35fdc681 wikidb: [62aa69b10ac402af1dc9e46d] /index.php?title=Special%3ACreateAccount   ParseError: syntax error, unexpected ''Buka menu samping dan ketuk $' (T_ENCAPSED_AND_WHITESPACE)
#0 /workspace/src/includes/language/LocalisationCache.php(1044): LCStoreStaticArray->startWrite(string)
#1 /workspace/src/includes/language/LocalisationCache.php(496): LocalisationCache->recache(string)
#2 /workspace/src/includes/language/LocalisationCache.php(370): LocalisationCache->initLanguage(string)
...

Looking at the debug log, I noticed that there are concurrent requests. LCStoreStaticArray::finishWrite() just writes to the output file with file_put_contents(), which is not safe for concurrent requests. There is a chance that other requests will see a partially written file.

tstarling added a comment.Dec 1 2022, 2:32 AM

Model:

<?php

require __DIR__ . '/../includes/WebStart.php';

$store = new LCStoreStaticArray( [ 'directory' => '/tmp/lcstore' ] );
$store->startWrite( 'en' );
$store->set( mt_rand( 1, 100000 ), mt_rand( 1, 1000 ) );
$store->finishWrite();

I ran it with

ab -n10000 -c10 -v1 .../lcstore-model.php

After about 2000 successful requests, the static array file was corrupted, and subsequent requests failed with ParseError: syntax error, unexpected token "=>". The resulting file had

<?php
// Generated by LCStoreStaticArray.php -- do not edit!
return [
// ...
	30069 => 954,
	87639 => 204,
	34112 => 964,
];
83 => 490,
];

I applied my patch, deleted the file, and ran the test again. Then all 10000 requests succeeded and the resulting file was still parseable, with about 5700 lines.

gerritbot added a comment.Dec 1 2022, 2:36 AM

Change 862401 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a project: Patch-For-Review.Dec 1 2022, 2:36 AM
gerritbot added a comment.Dec 1 2022, 11:42 PM

Change 862401 merged by jenkins-bot:

[mediawiki/core@master] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a comment.Dec 1 2022, 11:49 PM

Change 862913 had a related patch set uploaded (by Reedy; author: Tim Starling):

[mediawiki/core@REL1_39] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a comment.Dec 1 2022, 11:50 PM

Change 862914 had a related patch set uploaded (by Reedy; author: Tim Starling):

[mediawiki/core@REL1_38] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a comment.Dec 1 2022, 11:53 PM

Change 862915 had a related patch set uploaded (by Reedy; author: Tim Starling):

[mediawiki/core@REL1_35] LCStoreStaticArray: atomically replace the cache file

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

ReleaseTaggerBot added a project: MW-1.40-notes (1.40.0-wmf.13; 2022-12-05).Dec 2 2022, 12:01 AM
gerritbot added a comment.Dec 2 2022, 12:09 AM

Change 862915 merged by jenkins-bot:

[mediawiki/core@REL1_35] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a comment.Dec 2 2022, 12:10 AM

Change 862913 merged by jenkins-bot:

[mediawiki/core@REL1_39] LCStoreStaticArray: atomically replace the cache file

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

gerritbot added a comment.Dec 2 2022, 12:11 AM

Change 862914 merged by jenkins-bot:

[mediawiki/core@REL1_38] LCStoreStaticArray: atomically replace the cache file

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

ReleaseTaggerBot edited projects, added MW-1.39-notes, MW-1.38-notes, MW-1.35-notes; removed MW-1.39-notes (1.39.0-wmf.6; 2022-04-04).Dec 2 2022, 1:00 AM
matmarex closed this task as Resolved.Dec 2 2022, 5:29 PM
matmarex assigned this task to tstarling.

Thanks!

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL