Page MenuHomePhabricator

PHP7 corruption: Method call executed on unrelated object (also: Call to undefined method)
Open, MediumPublic

Description

Error
Error: Call to undefined method Monolog\Logger::get()

from /srv/mediawiki/php-1.35.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php:1303
trace
#0 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(558): WANObjectCache->getWithSetCallback(string, integer, Closure, array)
#1 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(414): CentralAuthUser->loadFromCache()
#2 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(589): CentralAuthUser->loadState()
#3 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CentralAuth/includes/CentralAuthUser.php(686): CentralAuthUser->getId()
#4 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CentralAuth/includes/CentralAuthHooks.php(917): CentralAuthUser->exists()
#5 /srv/mediawiki/php-1.35.0-wmf.19/includes/Hooks.php(174): CentralAuthHooks::onGetUserBlock(User, string, NULL)
#6 /srv/mediawiki/php-1.35.0-wmf.19/includes/Hooks.php(202): Hooks::callHook(string, array, array, NULL)
#7 /srv/mediawiki/php-1.35.0-wmf.19/includes/block/BlockManager.php(167): Hooks::run(string, array)
#8 /srv/mediawiki/php-1.35.0-wmf.19/includes/user/User.php(1800): MediaWiki\Block\BlockManager->getUserBlock(User, WebRequest, boolean)
#9 /srv/mediawiki/php-1.35.0-wmf.19/includes/user/User.php(2119): User->getBlockedStatus(boolean)
#10 /srv/mediawiki/php-1.35.0-wmf.19/includes/block/BlockManager.php(470): User->getBlock()
#11 /srv/mediawiki/php-1.35.0-wmf.19/includes/MediaWiki.php(755): MediaWiki\Block\BlockManager->trackBlockWithCookie(User, WebResponse)
#12 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiMain.php(548): MediaWiki::preOutputCommit(DerivativeContext)
#13 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiMain.php(493): ApiMain->executeActionWithErrorHandling()
#14 /srv/mediawiki/php-1.35.0-wmf.19/api.php(84): ApiMain->execute()
#15 /srv/mediawiki/w/api.php(3): require(string)
#16 {main}
  • Request ID: XkWMYwpAIDkAALfuQmcAAACH
  • Host: mw1345
  • Request Method: GET
  • Request URL: commons.wikimedia.org/w/api.php?action=query&generator=allimages&prop=imageinfo&…
  • phpversion: 7.2.26-1+0~20191218.33+debian9~1.gbpb5a340+wmf1
  • timestamp: 2020-02-13T17:51:28+00:00

Logstash record:
https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-deploy-2020.02.13/mediawiki?id=AXA_rVssh3Uj6x1zToLY

Source code

CentralAuthUser.php@1.35.0-wmf.19

		$cache = MediaWikiServices::getInstance()->getMainWANObjectCache();
		$data = $cache->getWithSetCallback( # line 540
			$this->getCacheKey( $cache ),
			$cache::TTL_DAY,
			function ( $oldValue, &$ttl, array &$setOpts ) {
				$dbr = CentralAuthUtils::getCentralReplicaDB();
				$setOpts += Database::getCacheSetOptions( $dbr );

				$this->loadFromDatabase();
				$this->loadAttached();
				$this->loadGroups();

				$data = [];
				foreach ( self::$mCacheVars as $var ) {
					$data[$var] = $this->$var;
				}

				return $data;
			},
			[ 'pcTTL' => $cache::TTL_PROC_LONG, 'version' => self::VERSION ] # line 558
		); # line 559

WANObjectCache.php@1.35.0-wmf.19

	final public function getWithSetCallback(
		$key, $ttl, $callback, array $opts = [], array $cbParams = []
	) {
		$version = $opts['version'] ?? null;
		$pcTTL = $opts['pcTTL'] ?? self::TTL_UNCACHEABLE;
		$pCache = ( $pcTTL >= 0 )
			? $this->getProcessCache( $opts['pcGroup'] ?? self::PC_PRIMARY )  # line 1296
			: null;

		if ( $pCache && $this->callbackDepth == 0 ) {
			$cached = $pCache->get( $this->getProcessCacheKey( $key, $version ), $pcTTL, false );   # line 1303
			if ( $cached !== false ) {
				$this->logger->debug( "getWithSetCallback($key): process cache hit" );  # line 1305
				return $cached;
			}
		}
Notes

Stuff is very messed up here:

  1. The error Call to undefined method Monolog\Logger::get() is attribued to line WANObjectCache.php:L1303, which is calling $pCache->get() where $pCache is an instance of MapCacheLRU. It is meant to be calling MapCacheLRU->get().
  2. For some reason the engine is thinking about Monolog\Logger, which is strange. For what it's worth, there is an instance of that object "near by" – two lines down on line 1305. Could it be confusing the two??
  3. The stack trace says WANObjectCache->getWithSetCallback was called from CentralAuthUser.php:L558. This is also odd, because that line is neither the start nor the end of the function call. See snippet above. Looks like this may be off by a few as well.

Might be opcache corruption.

Event Timeline

Krinkle created this task.Feb 13 2020, 6:29 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 13 2020, 6:29 PM
jijiki triaged this task as Medium priority.Feb 13 2020, 6:30 PM
jijiki added a project: serviceops.
jijiki added a subscriber: jijiki.
Krinkle renamed this task from Opcache corruption: Object and method magically missing to PHP7 corruption: Method call proxied to unrelated object (also: Call to undefined method).Feb 13 2020, 6:39 PM
Krinkle renamed this task from PHP7 corruption: Method call proxied to unrelated object (also: Call to undefined method) to PHP7 corruption: Method call executed on unrelated object (also: Call to undefined method).
Krinkle updated the task description. (Show Details)Feb 13 2020, 6:55 PM
Krinkle added a comment.EditedFeb 13 2020, 7:05 PM

Here is another mysterious mis-call which I can't explain:

Logstash single document

  • Host: mw1276
  • timestamp: 2020-02-13T04:10:15+00:00
Call to undefined method Wikibase\Repo\Hooks\Formatters\EntityLinkFormatterFactory::getSerialization()
 from /srv/mediawiki/php-1.35.0-wmf.19/vendor/wikibase/data-model-serialization/src/Serializers/StatementListSerializer.php:72
#0 /srv/mediawiki/php-1.35.0-wmf.19/vendor/wikibase/data-model-serialization/src/Serializers/StatementListSerializer.php(65): Wikibase\DataModel\Serializers\StatementListSerializer->getSerialized(Wikibase\DataModel\Statement\StatementList)
#1 /srv/mediawiki/php-1.35.0-wmf.19/vendor/wikibase/data-model-serialization/src/Serializers/ItemSerializer.php(127): Wikibase\DataModel\Serializers\StatementListSerializer->serialize(Wikibase\DataModel\Statement\StatementList)
#2 /srv/mediawiki/php-1.35.0-wmf.19/vendor/wikibase/data-model-serialization/src/Serializers/ItemSerializer.php(104): Wikibase\DataModel\Serializers\ItemSerializer->addStatementListToSerialization(Wikibase\DataModel\Entity\Item, array)
#3 /srv/mediawiki/php-1.35.0-wmf.19/vendor/wikibase/data-model-serialization/src/Serializers/ItemSerializer.php(94): Wikibase\DataModel\Serializers\ItemSerializer->getSerialized(Wikibase\DataModel\Entity\Item)
#4 /srv/mediawiki/php-1.35.0-wmf.19/vendor/serialization/serialization/src/Serializers/DispatchingSerializer.php(42): Wikibase\DataModel\Serializers\ItemSerializer->serialize(Wikibase\DataModel\Entity\Item)
#5 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Wikibase/client/includes/Serializer/ClientEntitySerializer.php(60): Serializers\DispatchingSerializer->serialize(Wikibase\DataModel\Entity\Item)
#6 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Wikibase/client/includes/DataAccess/Scribunto/EntityAccessor.php(163): Wikibase\Client\Serializer\ClientEntitySerializer->serialize(Wikibase\DataModel\Entity\Item)
#7 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Wikibase/client/includes/DataAccess/Scribunto/Scribunto_LuaWikibaseLibrary.php(414): Wikibase\Client\DataAccess\Scribunto\EntityAccessor->getEntity(string)
#8 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaSandbox/LuaSandboxCallback.php(26): Wikibase\Client\DataAccess\Scribunto\Scribunto_LuaWikibaseLibrary->getEntity(string)
#9 [internal function]: Scribunto_LuaSandboxCallback->__call(string, array)
#10 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaSandbox/LuaSandboxInterpreter.php(113): LuaSandboxFunction->call(LuaSandboxFunction)
#11 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaCommon/LuaEngine.php(291): Scribunto_LuaSandboxInterpreter->callFunction(LuaSandboxFunction, LuaSandboxFunction)
#12 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaCommon/LuaModule.php(69): Scribunto_LuaEngine->executeFunctionChunk(LuaSandboxFunction, PPTemplateFrame_Hash)
#13 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/common/Hooks.php(128): Scribunto_LuaModule->invoke(string, PPTemplateFrame_Hash)
#14 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3599): ScribuntoHooks::invokeHook(Parser, PPTemplateFrame_Hash, array)
#15 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3303): Parser->callParserFunction(PPTemplateFrame_Hash, string, array)
#16 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPTemplateFrame_Hash)
#17 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3481): PPFrame_Hash->expand(PPNode_Hash_Tree)
#18 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPFrame_Hash)
#19 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPTemplateFrame_Hash.php(169): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#20 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPTemplateFrame_Hash.php(181): PPTemplateFrame_Hash->getNamedArgument(string)
#21 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPTemplateFrame_Hash.php(113): PPTemplateFrame_Hash->getArgument(string)
#22 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaCommon/LuaEngine.php(691): PPTemplateFrame_Hash->getArguments()
#23 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaSandbox/LuaSandboxCallback.php(26): Scribunto_LuaEngine->getAllExpandedArguments(string)
#24 [internal function]: Scribunto_LuaSandboxCallback->__call(string, array)
#25 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaSandbox/LuaSandboxInterpreter.php(113): LuaSandboxFunction->call(LuaSandboxFunction)
#26 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaCommon/LuaEngine.php(291): Scribunto_LuaSandboxInterpreter->callFunction(LuaSandboxFunction, LuaSandboxFunction)
#27 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/engines/LuaCommon/LuaModule.php(69): Scribunto_LuaEngine->executeFunctionChunk(LuaSandboxFunction, PPTemplateFrame_Hash)
#28 /srv/mediawiki/php-1.35.0-wmf.19/extensions/Scribunto/includes/common/Hooks.php(128): Scribunto_LuaModule->invoke(string, PPTemplateFrame_Hash)
#29 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3599): ScribuntoHooks::invokeHook(Parser, PPTemplateFrame_Hash, array)
#30 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3303): Parser->callParserFunction(PPTemplateFrame_Hash, string, array)
#31 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPTemplateFrame_Hash)
#32 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3481): PPFrame_Hash->expand(PPNode_Hash_Tree)
#33 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPFrame_Hash)
#34 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(3144): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#35 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(1482): Parser->replaceVariables(string)
#36 /srv/mediawiki/php-1.35.0-wmf.19/includes/parser/Parser.php(598): Parser->internalParse(string)
#37 /srv/mediawiki/php-1.35.0-wmf.19/includes/content/WikitextContent.php(368): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#38 /srv/mediawiki/php-1.35.0-wmf.19/includes/content/AbstractContent.php(565): WikitextContent->fillParserOutput(Title, integer, ParserOptions, boolean, ParserOutput)
#39 /srv/mediawiki/php-1.35.0-wmf.19/includes/Revision/RenderedRevision.php(267): AbstractContent->getParserOutput(Title, integer, ParserOptions, boolean)
#40 /srv/mediawiki/php-1.35.0-wmf.19/includes/Revision/RenderedRevision.php(236): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached(WikitextContent, boolean)
#41 /srv/mediawiki/php-1.35.0-wmf.19/includes/Revision/RevisionRenderer.php(215): MediaWiki\Revision\RenderedRevision->getSlotParserOutput(string)
#42 /srv/mediawiki/php-1.35.0-wmf.19/includes/Revision/RevisionRenderer.php(152): MediaWiki\Revision\RevisionRenderer->combineSlotOutput(MediaWiki\Revision\RenderedRevision, array)
#43 [internal function]: MediaWiki\Revision\RevisionRenderer->MediaWiki\Revision\{closure}(MediaWiki\Revision\RenderedRevision, array)
#44 /srv/mediawiki/php-1.35.0-wmf.19/includes/Revision/RenderedRevision.php(198): call_user_func(Closure, MediaWiki\Revision\RenderedRevision, array)
#45 /srv/mediawiki/php-1.35.0-wmf.19/includes/filerepo/file/LocalFile.php(2097): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#46 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CommonsMetadata/src/DataCollector.php(290): LocalFile->getDescriptionText(LanguageEn)
#47 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CommonsMetadata/src/DataCollector.php(98): CommonsMetadata\DataCollector->getDescriptionText(LocalFile, LanguageEn)
#48 /srv/mediawiki/php-1.35.0-wmf.19/extensions/CommonsMetadata/src/HookHandler.php(70): CommonsMetadata\DataCollector->collect(array, LocalFile)
#49 /srv/mediawiki/php-1.35.0-wmf.19/includes/Hooks.php(174): CommonsMetadata\HookHandler::onGetExtendedMetadata(array, LocalFile, RequestContext, boolean, integer)
#50 /srv/mediawiki/php-1.35.0-wmf.19/includes/Hooks.php(202): Hooks::callHook(string, array, array, NULL)
#51 /srv/mediawiki/php-1.35.0-wmf.19/includes/media/FormatMetadata.php(1707): Hooks::run(string, array)
#52 /srv/mediawiki/php-1.35.0-wmf.19/includes/media/FormatMetadata.php(1624): FormatMetadata->getExtendedMetadataFromHook(LocalFile, array, integer)
#53 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiQueryImageInfo.php(575): FormatMetadata->fetchExtendedMetadata(LocalFile)
#54 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiQueryImageInfo.php(183): ApiQueryImageInfo::getInfo(LocalFile, array, ApiResult, NULL, array)
#55 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiQuery.php(255): ApiQueryImageInfo->execute()
#56 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiMain.php(1586): ApiQuery->execute()
#57 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiMain.php(522): ApiMain->executeAction()
#58 /srv/mediawiki/php-1.35.0-wmf.19/includes/api/ApiMain.php(493): ApiMain->executeActionWithErrorHandling()
#59 /srv/mediawiki/php-1.35.0-wmf.19/api.php(84): ApiMain->execute()
#60 /srv/mediawiki/w/api.php(3): require(string)
#61 {main}

Source code: StatementListSerializer.php

	private function getSerialized( StatementList $statementList ) {
		// …

		foreach ( $statementList->toArray() as $statement ) {
			$statement->getPropertyId()->getSerialization(); # line 72

However the class it says it has an instance of (EntityLinkFormatterFactory) doesn't seem to be related to this.

Source code: EntityLinkFormatterFactory.php

namespace Wikibase\Repo\Hooks\Formatters;

/* … */
class EntityLinkFormatterFactory {

Definitely not what getPropertyId() would return an instance of.

I looked at the code base and couldn't find any instance that EntityLinkFormatterFactory object would be set as property id of an statement. Unless some eval magic is involved and we would have bad lua in clients invoking this but I highly highly doubt that.

Krinkle added a comment.EditedMar 17 2020, 1:47 AM

Here is another mysterious mis-call (Logstash single document)

  • timestamp: 2020-02-14T10:04:16
  • reqId: XkZwYwpAICkAAAmWLyEAAAAL
  • host: mw1320
PHP Fatal Error: Uncaught Error: Call to a member function isHandling() on integer

in /srv/mediawiki/php-1.35.0-wmf.19/vendor/monolog/monolog/src/Monolog/Logger.php:304
#0 /srv/mediawiki/php-1.35.0-wmf.19/vendor/monolog/monolog/src/Monolog/Logger.php(628): Monolog\Logger->addRecord(100, 'getWithSetCallb...', Array)
#1 /srv/mediawiki/php-1.35.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1305): Monolog\Logger->debug('getWithSetCallb...')

The code in question:

WANObjectCache
setLogger( LoggerInterface $logger ) {
	$this->logger = $logger;
}
getWithSetCallback(  ) {
	
	$this->logger->debug( "getWithSetCallback($key): process cache hit" );
Monolog/Logger
public function debug($message, array $context = array()) {
  return $this->addRecord(static::DEBUG, $message, $context);
}
public function addRecord(int $level, string $message, array $context = array()) {
   $this->handlers = [  ]; // @var HandlerInterface[]
    

    $levelName = static::getLevelName($level); // @var string
    reset($this->handlers);
    while ($handler = current($this->handlers)) {
        if ($handler->isHandling(array('level' => $level))) { # BOOM

In this case it looks like PHP has somehow confused $handler (HandlerInterface) with $level (integer).

Here is another mysterious mis-call (Logstash single document)

  • timestamp: 2020-02-14T10:04:16
  • reqId: XkZwYwpAICkAAAmWLyEAAAAL
  • host: mw1320
PHP Fatal Error: Uncaught Error: Call to a member function isHandling() on integer

in /srv/mediawiki/php-1.35.0-wmf.19/vendor/monolog/monolog/src/Monolog/Logger.php:304
#0 /srv/mediawiki/php-1.35.0-wmf.19/vendor/monolog/monolog/src/Monolog/Logger.php(628): Monolog\Logger->addRecord(100, 'getWithSetCallb...', Array)
#1 /srv/mediawiki/php-1.35.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1305): Monolog\Logger->debug('getWithSetCallb...')

It does not appear to align with an automatic restart (the next one was several days later), and also does not align with a near-zero amount of opcache memory left. Odd?

Error message
Fatal error:
Cannot declare class Wikimedia\MWConfig\XWikimediaDebug, because the name is already in use
Notes

A spike of over 7000 fatals in the span of one hour, on the mw1379 server.

It lasted approximately from 2020-06-01 14:00 to 14:50 UTC.

From Logstash mediawiki-errors:

Impact

All wiki web requests on this server were presumably aborted with a system error.