Page MenuHomePhabricator

ResourceLoaderWikiModule.php: PHP Notice: Undefined index:
Closed, ResolvedPublic

Description

Error

Request ID: XUGdgwpAIDwAAA3dweYAAABE
Request URL: /w/api.php

message
PHP Notice: Undefined index: 

(this means the key was '', empty string)
trace
#0 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderWikiModule.php(394): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderWikiModule.php(347): ResourceLoaderWikiModule->getTitleInfo(DerivativeResourceLoaderContext)
#2 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderClientHtml.php(146): ResourceLoaderWikiModule->isKnownEmpty(DerivativeResourceLoaderContext)
#3 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderClientHtml.php(326): ResourceLoaderClientHtml->getData()
#4 /srv/mediawiki/php-1.34.0-wmf.15/includes/OutputPage.php(3159): ResourceLoaderClientHtml->getBodyHtml()
#5 /srv/mediawiki/php-1.34.0-wmf.15/includes/skins/Skin.php(683): OutputPage->getBottomScripts()
#6 /srv/mediawiki/php-1.34.0-wmf.15/includes/skins/SkinTemplate.php(457): Skin->bottomScripts()
#7 /srv/mediawiki/php-1.34.0-wmf.15/includes/skins/SkinTemplate.php(217): SkinTemplate->prepareQuickTemplate()
#8 /srv/mediawiki/php-1.34.0-wmf.15/includes/OutputPage.php(2580): SkinTemplate->outputPage()
#9 /srv/mediawiki/php-1.34.0-wmf.15/includes/api/ApiHelp.php(56): OutputPage->output()
#10 /srv/mediawiki/php-1.34.0-wmf.15/includes/api/ApiMain.php(1583): ApiHelp->execute()
#11 /srv/mediawiki/php-1.34.0-wmf.15/includes/api/ApiMain.php(531): ApiMain->executeAction()
#12 /srv/mediawiki/php-1.34.0-wmf.15/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling()
#13 /srv/mediawiki/php-1.34.0-wmf.15/api.php(86): ApiMain->execute()
#14 /srv/mediawiki/w/api.php(3): require(string)
Impact

Limited corruption within the PHP process. Not persisted in DB or Memcached.

Affects only every few backend requests.

But, it affects version hashes (via getDefinitionSummary), and is Varnish. This means the more rare the error is, the worse it is. If it was a common error that affects all servers, they would all agree on the hash. But given they don't this means that if the rare response ends up Varnish, all browsers will refuse caching certain modules due to the hash not matching with other backend responses.

Notes

The same requests also have a second error logged shorter further on, which is a side-effect of the first one being non-fatal in the PHP engine.

message 2
PHP Warning: count(): Parameter must be an array or an object that implements Countable

#0 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderWikiModule.php(367): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.34.0-wmf.15/includes/resourceloader/ResourceLoaderClientHtml.php(146): ResourceLoaderWikiModule->isKnownEmpty(DerivativeResourceLoaderContext)
…

Event Timeline

Krinkle created this task.Jul 31 2019, 3:08 PM
Restricted Application added a project: Performance-Team. · View Herald TranscriptJul 31 2019, 3:08 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Krinkle added a comment.EditedJul 31 2019, 3:12 PM

This issue was previously found when investigating opcache corruptions, from PyBall monitoring requests (T224491). Per this task, it is found outside monitoring requests as well now.

But, still limited to PHP 7.2. No instances of the issue have been found on HHVM yet.

A simplified version of the code in question (https://3v4l.org/vKJaS):

class Foo {
    protected $titleInfo = [];
 
    /** @return array */
    public function bar() {
        $key = '';
        if ( !isset( $this->titleInfo[$key] ) ) {
            $this->titleInfo[$key] = [ 42 ];
        }
        return $this->titleInfo[$key]; # The critical line
    }
}

$value = ( new Foo )->bar();
var_dump( $value );

This normally results in the critical line successfully yielding an array containing the number 42. However, in production we see this sometimes raises a warning on the critical line for "Undefined index: " ($key - empty string), which then results in the method returning NULL which then causes various cascading failures due to its return contract being violated.

Change 526704 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] resourceloader: Debugging in WikiModule for T229433

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

Change 526705 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.34.0-wmf.15] resourceloader: Debugging in WikiModule for T229433

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

Change 526706 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.34.0-wmf.16] resourceloader: Debugging in WikiModule for T229433

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

Change 526705 abandoned by Krinkle:
resourceloader: Debugging in WikiModule for T229433

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

Krinkle claimed this task.Aug 6 2019, 5:58 PM
Krinkle triaged this task as High priority.
kchapman moved this task from Inbox to Doing on the Performance-Team board.Aug 6 2019, 7:56 PM

Change 526706 abandoned by Krinkle:
resourceloader: Debugging in WikiModule for T229433

Reason:
Obsolete.

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

Change 531228 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.34.0-wmf.17] resourceloader: Debugging in WikiModule for T229433

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

Change 531229 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.34.0-wmf.19] resourceloader: Debugging in WikiModule for T229433

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

Change 531229 merged by Krinkle:
[mediawiki/core@wmf/1.34.0-wmf.19] resourceloader: Debugging in WikiModule for T229433

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

Mentioned in SAL (#wikimedia-operations) [2019-08-20T16:15:00Z] <krinkle@deploy1001> Synchronized php-1.34.0-wmf.19/includes/resourceloader/ResourceLoaderWikiModule.php: T229433 - 44607c984016b (debugging) (duration: 00m 55s)

Change 531228 merged by jenkins-bot:
[mediawiki/core@wmf/1.34.0-wmf.17] resourceloader: Debugging in WikiModule for T229433

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

Mentioned in SAL (#wikimedia-operations) [2019-08-20T16:49:31Z] <krinkle@deploy1001> Synchronized php-1.34.0-wmf.17/includes/resourceloader/ResourceLoaderWikiModule.php: T229433 - f84a4abb418de8 (debugging) (duration: 00m 56s)

Krinkle added a comment.EditedSat, Aug 24, 5:57 PM

Got a sample in the logs. This is most puzzling.

ResourceLoaderWikiModule.php
	protected function getTitleInfo( ResourceLoaderContext $context ) {
		$batchKey = "";
		if ( !isset( $this->titleInfo[$batchKey] ) ) {
			$this->titleInfo[$batchKey] = [ compute() ];
		}
		// …
		if ( !isset( $this->titleInfo[$batchKey] ) ) {
			// Should be impossible!
			$this->logger->warning( 'ResourceLoaderWikiModule titleInfo key bug', [  ] );
		}

		$titleInfo = $this->titleInfo[$batchKey]; # PHP Notice: Undefined index: ''
ResourceLoaderWikiModule.php (instrumented)
	protected function getTitleInfo( ResourceLoaderContext $context ) {
		$tmpDidAssignment = 0;
		$tmpAssignedValue = -1;
		// …
		$batchKey = ; # string(0) ""
		if ( !isset( $this->titleInfo[$batchKey] ) ) {
			$tmpAssignedValue = static::fetchTitleInfo(  );
			$this->titleInfo[$batchKey] = $tmpAssignedValue;
			$tmpDidAssignment = 1;
		}
		// …
		if ( @$this->titleInfo[$batchKey] === null ) {
			// …
			$this->logger->warning( 'ResourceLoaderWikiModule titleInfo key bug', [
				'assignDid' => $tmpDidAssignment, # int(1) 1
				'assignFetchedValue' => $tmpAssignedValue, # array(0) []
				'trace' => ,
			] );
		}

		$titleInfo = $this->titleInfo[$batchKey]; # PHP Notice: Undefined index: 

Logstash: Single document.

Logstash(1)
2019-08-23T15:21:57 WARNING resourceloader mw1227 jawiki ResourceLoaderWikiModule titleInfo key bug
 reqId: XWAElQpAMD4AAJs0aJ4AAABG
 url: /w/api.php
 http_method: POST

 "assignDid": 1,
 "assignFetchedValue": [],

 trace:
#0 /srv/mediawiki/php-1.34.0-wmf.19/includes/resourceloader/ResourceLoaderWikiModule.php(347): ResourceLoaderWikiModule->getTitleInfo(Object(ResourceLoaderContext))
#1 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(2975): ResourceLoaderWikiModule->isKnownEmpty(Object(ResourceLoaderContext))
#2 [internal function]: OutputPage->{closure}('ext.globalCssJs...')
#3 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(2983): array_filter(Array, Object(Closure))
#4 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(3160): OutputPage->getRlClient()
#5 …
#8 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(2581): SkinTemplate->outputPage()
#9 /srv/mediawiki/php-1.34.0-wmf.19/includes/api/ApiHelp.php(56): OutputPage->output()
#10 /srv/mediawiki/php-1.34.0-wmf.19/includes/api/ApiMain.php(1589): ApiHelp->execute()
#11 …
Logstash(2)
2019-08-23T15:21:57 ERROR error mw1227 jawiki PHP Notice: Undefined index: 
 reqId: XWAElQpAMD4AAJs0aJ4AAABG
 url: /w/api.php
 http_method: POST
 message:

 ErrorException from line 407 of /srv/mediawiki/php-1.34.0-wmf.19/includes/resourceloader/ResourceLoaderWikiModule.php: PHP Notice: Undefined index: 

 exception.trace:
#0 /srv/mediawiki/php-1.34.0-wmf.19/includes/resourceloader/ResourceLoaderWikiModule.php(407): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.34.0-wmf.19/includes/resourceloader/ResourceLoaderWikiModule.php(347): ResourceLoaderWikiModule->getTitleInfo(ResourceLoaderContext)
#2 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(2975): ResourceLoaderWikiModule->isKnownEmpty(ResourceLoaderContext)
#3 [internal function]: OutputPage->{closure}(string)
#4 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(2983): array_filter(array, Closure)
#5 /srv/mediawiki/php-1.34.0-wmf.19/includes/OutputPage.php(3160): OutputPage->getRlClient()
#6 …

What we know:

  • $batchKey is string(0) "".
  • Initially $this->titleInfo[$batchKey] is not set. Which means !isset() returns true and we enter the conditional branch.
  • fetchTitleInfo returns an empty array.
  • The assignment is reached successfully, as is the line below it.
  • After the conditional branch and its assignment, the key is still not set, causing the PHP Notice: Undefined index: error on line 407. Further confirmed by the $… === null check, from which we log the extra data.

How is this possible !?

Only three instances in the logs in 5 days. Maybe it should throw an exception instead of just logging a warning, to avoid breaking the caches? I investigated whether it could be an instance of https://bugs.php.net/bug.php?id=78379 -- it seems unlikely, since I couldn't find anywhere where getDefinitionSummary() is cast to an object. I guess the most likely thing is that there is something wrong with the array, causing the assignment to be effectively ignored. A core dump would help to narrow it down.

This would probably be enough to make it successfully do a core dump in production:

posix_setrlimit( POSIX_RLIMIT_CORE, 10e9, POSIX_RLIMIT_INFINITY );
posix_kill( posix_getpid(), SIGABRT );
mmodell changed the subtype of this task from "Task" to "Production Error".Wed, Aug 28, 11:06 PM
brion added a subscriber: brion.Wed, Sep 11, 9:15 PM

Looks like in PHP 7.2 the empty string gets interned to a special shared instance (zend_empty_string)... It's possible something's corrupting zend_empty_string, either its contents or its hash (h) field. If we can get a core dump it should be possible to inspect the symbol...

hashar added a subscriber: hashar.EditedWed, Sep 11, 9:16 PM

T232613 seems very similar but occurs way more frequently (~ 180 occurrences over four hours). Maybe that can be used to generate the core dump Tim has suggested?

jijiki renamed this task from Investigate magically missing array key in ResourceLoaderWikiModule to ResourceLoaderWikiModule.php: PHP Notice: Undefined index: .Thu, Sep 12, 2:26 PM
hashar changed the task status from Open to Stalled.Thu, Sep 12, 9:56 PM

I have made production to generate a core dump, there is already one captured T232613#5489237 . Lets centralize on T232613 for now which is the most frequent occurrence.

The issue should now have been solved. There was an issue in the memcached PHP module. The fix has been deployed on Sep 16th around noon. More details: T232613#5494695

Krinkle closed this task as Resolved.Mon, Sep 16, 7:14 PM

No longer seen in WMF Logstash since resolution of T232613#5494695.