Page MenuHomePhabricator

ParameterAssertionException "Bad value for parameter $row->rev_timestamp" from RevisionStoreRecord.php
Open, HighPublicPRODUCTION ERROR

Description

Error message
Wikimedia\Assert\ParameterAssertionException:
Bad value for parameter $row->rev_timestamp: must be a valid timestamp
Stack Trace
#0 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionStoreRecord.php(73): Wikimedia\Assert\Assert::parameter(boolean, string, string)
#1 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionStoreCacheRecord.php(67): MediaWiki\Revision\RevisionStoreRecord->__construct(Title, User, CommentStoreComment, stdClass, MediaWiki\Revision\RevisionSlots, boolean)
#2 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionStore.php(1518): MediaWiki\Revision\RevisionStoreCacheRecord->__construct(Closure, Title, User, CommentStoreComment, stdClass, MediaWiki\Revision\RevisionSlots, boolean)
#3 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionStore.php(1360): MediaWiki\Revision\RevisionStore->newRevisionFromRowAndSlots(stdClass, MediaWiki\Revision\RevisionSlots, integer, Title, boolean)
#4 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionStore.php(2903): MediaWiki\Revision\RevisionStore->newRevisionFromRow(stdClass, integer, Title, boolean)
#5 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3473): MediaWiki\Revision\RevisionStore->getKnownCurrentRevision(Title)
#6 [internal function]: Parser::statelessFetchRevision(Title, Parser)
#7 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RenderedRevision.php(391): call_user_func(array, Title, Parser)
#8 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/ParserOptions.php(841): MediaWiki\Revision\RenderedRevision->MediaWiki\Revision\{closure}(Title, Parser)
#9 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3440): ParserOptions->{closure}(Title, Parser)
#10 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3409): Parser->fetchCurrentRevisionRecordOfTitle(Title)
#11 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3576): Parser->fetchCurrentRevisionOfTitle(Title)
#12 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3501): Parser->statelessFetchTemplate(Title, Parser)
#13 /srv/mediawiki/php-1.35.0-wmf.34/extensions/Scribunto/includes/common/ScribuntoEngineBase.php(167): Parser->fetchTemplateAndTitle(Title)
#14 /srv/mediawiki/php-1.35.0-wmf.34/extensions/Scribunto/includes/common/Hooks.php(110): ScribuntoEngineBase->fetchModuleFromParser(Title)
#15 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3317): ScribuntoHooks::invokeHook(Parser, PPTemplateFrame_Hash, array)
#16 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3021): Parser->callParserFunction(PPTemplateFrame_Hash, string, array)
#17 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPTemplateFrame_Hash)
#18 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(3199): PPFrame_Hash->expand(PPNode_Hash_Tree)
#19 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/PPFrame_Hash.php(253): Parser->braceSubstitution(array, PPFrame_Hash)
#20 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(2862): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#21 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(1548): Parser->replaceVariables(string)
#22 /srv/mediawiki/php-1.35.0-wmf.34/includes/parser/Parser.php(635): Parser->internalParse(string)
#23 /srv/mediawiki/php-1.35.0-wmf.34/includes/content/WikitextContent.php(368): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#24 /srv/mediawiki/php-1.35.0-wmf.34/includes/content/AbstractContent.php(565): WikitextContent->fillParserOutput(Title, integer, ParserOptions, boolean, ParserOutput)
#25 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RenderedRevision.php(267): AbstractContent->getParserOutput(Title, integer, ParserOptions, boolean)
#26 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RenderedRevision.php(236): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached(WikitextContent, boolean)
#27 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionRenderer.php(215): MediaWiki\Revision\RenderedRevision->getSlotParserOutput(string)
#28 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RevisionRenderer.php(152): MediaWiki\Revision\RevisionRenderer->combineSlotOutput(MediaWiki\Revision\RenderedRevision, array)
#29 [internal function]: MediaWiki\Revision\RevisionRenderer->MediaWiki\Revision\{closure}(MediaWiki\Revision\RenderedRevision, array)
#30 /srv/mediawiki/php-1.35.0-wmf.34/includes/Revision/RenderedRevision.php(198): call_user_func(Closure, MediaWiki\Revision\RenderedRevision, array)
#31 /srv/mediawiki/php-1.35.0-wmf.34/includes/filerepo/file/LocalFile.php(2196): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#32 /srv/mediawiki/php-1.35.0-wmf.34/extensions/CommonsMetadata/src/DataCollector.php(290): LocalFile->getDescriptionText(LanguageEn)
#33 /srv/mediawiki/php-1.35.0-wmf.34/extensions/CommonsMetadata/src/DataCollector.php(98): CommonsMetadata\DataCollector->getDescriptionText(LocalFile, LanguageEn)
#34 /srv/mediawiki/php-1.35.0-wmf.34/extensions/CommonsMetadata/src/HookHandler.php(70): CommonsMetadata\DataCollector->collect(array, LocalFile)
#35 /srv/mediawiki/php-1.35.0-wmf.34/includes/HookContainer/HookContainer.php(313): CommonsMetadata\HookHandler::onGetExtendedMetadata(array, LocalFile, RequestContext, boolean, integer)
#36 /srv/mediawiki/php-1.35.0-wmf.34/includes/HookContainer/HookContainer.php(125): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#37 /srv/mediawiki/php-1.35.0-wmf.34/includes/Hooks.php(136): MediaWiki\HookContainer\HookContainer->run(string, array, array)
#38 /srv/mediawiki/php-1.35.0-wmf.34/includes/media/FormatMetadata.php(1710): Hooks::run(string, array)
#39 /srv/mediawiki/php-1.35.0-wmf.34/includes/media/FormatMetadata.php(1627): FormatMetadata->getExtendedMetadataFromHook(LocalFile, array, integer)
#40 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiQueryImageInfo.php(576): FormatMetadata->fetchExtendedMetadata(LocalFile)
#41 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiQueryImageInfo.php(184): ApiQueryImageInfo::getInfo(LocalFile, array, ApiResult, NULL, array)
#42 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiQuery.php(263): ApiQueryImageInfo->execute()
#43 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiMain.php(1583): ApiQuery->execute()
#44 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiMain.php(523): ApiMain->executeAction()
#45 /srv/mediawiki/php-1.35.0-wmf.34/includes/api/ApiMain.php(494): ApiMain->executeActionWithErrorHandling()
#46 /srv/mediawiki/php-1.35.0-wmf.34/api.php(84): ApiMain->execute()
#47 /srv/mediawiki/w/api.php(3): require(string)
Impact

Some pages cannot be viewed due to the Parser being unable to fetch a particular template from RevisionStore.

The above shows that it also affects API queries where that same template or a page using the template is parsed, such as ApiQueryImageInfo and CommonsMetadata.

Notes

The request that encountered this error used a generator which makes it hard to determine exactly which template reportedly has a corrupt revision row.

Details

Request ID
87c2c626-7063-4526-b94b-8975aa7f3a52
Request URL
commonswiki /w/api.php?action=query&generator=allimages&…&prop=imageinfo&…&iiprop=url|user|dimensions|extmetadata&…

Event Timeline

Change 602186 had a related patch set uploaded (by Ppchelko; owner: Ppchelko):
[mediawiki/core@master] Add more data to the rev_timestamp assertion error for debugging

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

Pchelolo added a subscriber: Pchelolo.

I tried to find the corrupted template, but it appeared to be impossible. The above patch adds more data to the exception so that investigation can continue.

Change 602186 merged by jenkins-bot:
[mediawiki/core@master] Add more data to the rev_timestamp assertion error for debugging

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

Logging enhancement has been deployed. Now on commons wiki we see: Bad value for parameter $row->rev_timestamp: must be a valid timestamp (rev_id=367335663, rev_timestamp=20190920175225)

The rev_timestamp in the database for this revision is indeed 20190920175225

What is invalid about it?

That is my question as well... I didn't have time to dig into this more yet, but it's very strange.

Numerous samples can be found via https://logstash.wikimedia.org/goto/36bf0b57cfd3e272d7faa17e67620f93.

  • 2020-06-10T17:14:17 mw1285 commonswiki Bad value for parameter $row->rev_timestamp: must be a valid timestamp (rev_id=367335663, rev_timestamp=20190920175225)
  • 2020-06-10T13:44:29 mw1394 commonswiki Bad value for parameter $row->rev_timestamp: must be a valid timestamp (rev_id=375848924, rev_timestamp=20191117041600)

For each of these, I am unable to reproduce the logic (source) it in isolation from the command-line:

RevisionStoreRecord.php
		$timestamp = MWTimestamp::convert( TS_MW, $row->rev_timestamp );
		Assert::parameter(
			is_string( $timestamp ),
			'$row->rev_timestamp',
			"must be a valid timestamp (rev_id={$this->mId}, rev_timestamp={$row->rev_timestamp})"
		);
eval
> var_dump( MWTimestamp::convert( TS_MW, '20190920175225' ) );
string(14) "20190920175225"

I wonder if this could be due to php opcache corruption (ref T253673). For example, if the defition of the TS_MW constant or some other part of wikimedia/timestamp got corrupted, it would likely lead to setTimestamp (internal call from ::convert()) throwing an exception, which ::convert() catches and then returns boolean false for.

I wonder if this could be due to php opcache corruption (ref T253673).

I see six occurrences over 7 days, all from different hosts. If the opcache got corrupted, wouldn't that cause similar errors for many requests on a single host? I'd imagine a lot of stuff would blow up if e.g. the value of TS_MW was messed up...

I see six occurrences over 7 days, all from different hosts. If the opcache got corrupted, wouldn't that cause similar errors for many requests on a single host? I'd imagine a lot of stuff would blow up if e.g. the value of TS_MW was messed up...

No, in my experience opcache corruptions do not tend to behave that way. Virtually all that I've encountered so far are one-off and not seen again for some time until hours/days later, and then likely on a different server. See past examples at T245183, and T224491.

It would be interesting to see if the rate of occurrence changes after T266055 is deployed.

I see two places in ConvertibleTimestamp.php that recast generic "Exception" errors into "TimestampException", which would make convert() return false, which could cause this problem.

I see two places in ConvertibleTimestamp.php that recast generic "Exception" errors into "TimestampException", which would make convert() return false, which could cause this problem.

Indeed. Also, FWIW I've just tried this on frwiki using the value from https://logstash.wikimedia.org/app/discover#/doc/logstash-*/logstash-deploy-2021.03.08?id=9kgJEngBWKe2MTdRm7f2, but I cannot reproduce it. I think it would be useful to log what's causing the TimestampException to be thrown. ConvertibleTimestamp::convert() is essentially swallowing any potentially useful information. However, since that is library code, I think it wouldn't be practical to add a dependency on a logger. Instead, we might add

public static function convertThrow( $style, $ts ) : string {
	$ct = new static( $ts );
	return $ct->getTimestamp( $style );
}

for places (like RevisionStore) that require a valid timestamp, so they don't have to check for false, and we would also preserve detailed information about the error.

Oh wait but that's already possible:

( new ConvertibleTimestamp() )->getTimestamp()

this can already be used in RevisionStore.

Change 669842 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/core@master] RevisionStoreRecord: Use MWTimestamp::getTimestamp for detailed errors

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

Change 669842 merged by jenkins-bot:

[mediawiki/core@master] RevisionStoreRecord: Use MWTimestamp::getTimestamp for detailed errors

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

Last seen on April 6. Seems fixed, but hard to be sure, the error only occurred one a week or so before.

Last seen on April 6. Seems fixed, but hard to be sure, the error only occurred one a week or so before.

The error message would be different now though. It would be an uncaught TimestampException. However, I'm not seeing any TimestampException from RevisionStoreRecord on logstash. Guess we might want to wait a bit more.