Page MenuHomePhabricator

serialize(): "" returned as member variable from __sleep() but does not exist
Open, NormalPublic

Description

Error

Request URL: /w/index.php?title=Andoza:LQT_page_converted_to_Flow&variant=uz-cyrl
Request ID: XUCXPApAMFkAAGZv-TEAAABO

message
serialize(): "" returned as member variable from __sleep() but does not exist
trace
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 [internal function]: Memcached->setByKey(string, string, ParserOutput, integer)
#2 /srv/mediawiki/php-1.34.0-wmf.16/includes/libs/objectcache/MemcachedPeclBagOStuff.php(209): Memcached->set(string, ParserOutput, integer)
#3 /srv/mediawiki/php-1.34.0-wmf.16/includes/libs/objectcache/MediumSpecificBagOStuff.php(168): MemcachedPeclBagOStuff->doSet(string, ParserOutput, integer, integer)
#4 /srv/mediawiki/php-1.34.0-wmf.16/includes/libs/objectcache/MultiWriteBagOStuff.php(325): MediumSpecificBagOStuff->set(string, ParserOutput, integer)
#5 /srv/mediawiki/php-1.34.0-wmf.16/includes/libs/objectcache/MultiWriteBagOStuff.php(137): MultiWriteBagOStuff->doWrite(array, boolean, string, array)
#6 /srv/mediawiki/php-1.34.0-wmf.16/includes/parser/ParserCache.php(260): MultiWriteBagOStuff->get(string, integer)
#7 /srv/mediawiki/php-1.34.0-wmf.16/includes/page/Article.php(691): ParserCache->get(WikiPage, ParserOptions)
#8 /srv/mediawiki/php-1.34.0-wmf.16/includes/actions/ViewAction.php(63): Article->view()
#9 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(507): ViewAction->show()
#10 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(302): MediaWiki->performAction(Article, Title)
#11 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(892): MediaWiki->performRequest()
#12 /srv/mediawiki/php-1.34.0-wmf.16/includes/MediaWiki.php(523): MediaWiki->main()
#13 /srv/mediawiki/php-1.34.0-wmf.16/index.php(42): MediaWiki->run()
#14 /srv/mediawiki/w/index.php(3): include(string)
#15 {main}

Impact

Notes

Exploded after deploy to Group0, so far has not subsided. Seems likely to be a lot of noise for Group1.

Event Timeline

brennen created this task.Jul 30 2019, 7:24 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 30 2019, 7:24 PM
brennen triaged this task as Unbreak Now! priority.Jul 30 2019, 7:27 PM

Setting UBN! and adding as a train blocker. Not rolling back Group0 for now.

Restricted Application added a subscriber: Liuxinyu970226. · View Herald TranscriptJul 30 2019, 7:27 PM
brennen added a subscriber: aaron.Jul 30 2019, 7:42 PM

Looking through changelog, Aaron seems to have commit messages with cache-related stuff. Adding for that reason.

Not rolling back Group0 for now.

Rolled back Group0 a bit ago, as notices didn't appear to be meaningfully decreasing.

I think probably not, but I'm also wondering if @Krinkle's objectcache: Use variadic signature for makeKey() might be relevant.

Krinkle added a comment.EditedJul 30 2019, 10:33 PM

Yes, this should be rolled back from group0 as well. Looks like something that will cause corruption and is not easily reversible/recoverable.

The makeKey() patch won't be related. That method is well-tested and already called successfully before this point is reached.

It'll likely be one of these:

  • The MediumSpecificBagOStuff refactor – bebe30333df8 / https://gerrit.wikimedia.org/r/522079
  • The object segmentation feature (introduced in b09b3980f9 as dormant feature), can't find the commit but maybe the feature was enabled this week?
  • .. something else that is specific to Memcached, ParserOutput or PHP 7.

Thanks for investigating!

Yes, this should be rolled back from group0 as well.

For clarity: 1.34.0-wmf.16 hasn't been deployed to any group since ~19:39 UTC.

I believe it might be due to 5099ee9f727 / https://gerrit.wikimedia.org/r/519352, which does the following:

class ParserOutput {
	private static $speculativeFields = [
		'speculativePageIdUsed',
		'speculativeRevIdUsed',
		'revisionTimestampUsed'
	];
	public function mergeInternalMetaDataFrom( ParserOutput $source ) {
		// …

		foreach ( self::$speculativeFields as $field ) {
			if (  ) {
				
			}
			$this->$field = $this->useMaxValue( $this->$field, $source->$field );
		}

Previous (bad) experience with cached serialised ParserOutput objects tells me this might be executing in a way that $speculativeFields won't exist properly and maybe somehow causes this to set $this->{""} with $this->$field.

Change 526555 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] Revert "objectcache: add MediumSpecificBagOStuff base class for non-proxy subclasses"

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

Previous (bad) experience with cached serialised ParserOutput objects tells me this might be executing in a way that $speculativeFields won't exist properly and maybe somehow causes this to set $this->{""} with $this->$field.

Even a private static variable accessed with self:: may not exist? That should just come from the definition of currently executing code, not from the object. And even if it were null, you still wouldn't end up with $field = ''.

Mentioned in SAL (#wikimedia-operations) [2019-07-31T01:08:37Z] <TimStarling> on mwmaint1002, editing wikiversions.json locally to move wikimania2006wiki to .16, to investigate T229366

I was able to reproduce this in eval.php. The problem is that the private member variable mSpeculativeRevId was renamed to speculativeRevIdUsed in 5099ee9f727. When you unserialize a ParserOutput from before that change, you end up with a dynamic member variable with the masked name "\0ParserOutput\0mSpeculativeRevId". That is the string returned by array_keys(get_object_vars($this)). That is not a valid thing to return from __sleep(). Evidently at some point the string is interpreted as null-terminated, which is why it appears to be an empty string in the error message.

Change 526575 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/core@master] Revert rename of mSpeculativeRevId to speculativeRevIdUsed

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

Change 526575 merged by jenkins-bot:
[mediawiki/core@master] Revert rename of mSpeculativeRevId to speculativeRevIdUsed

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

Change 526584 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/core@wmf/1.34.0-wmf.16] [1.34.0-wmf.16] Revert rename of mSpeculativeRevId to speculativeRevIdUsed

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

Change 526584 merged by jenkins-bot:
[mediawiki/core@wmf/1.34.0-wmf.16] [1.34.0-wmf.16] Revert rename of mSpeculativeRevId to speculativeRevIdUsed

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

Mentioned in SAL (#wikimedia-operations) [2019-07-31T03:59:32Z] <tstarling@deploy1001> Synchronized php-1.34.0-wmf.16/includes/parser/ParserOutput.php: T229366 (duration: 00m 47s)

Mentioned in SAL (#wikimedia-operations) [2019-07-31T04:00:38Z] <tstarling@deploy1001> Synchronized php-1.34.0-wmf.16/tests/phpunit/includes/parser/ParserOutputTest.php: T229366 (duration: 00m 46s)

tstarling closed this task as Resolved.Jul 31 2019, 4:03 AM
tstarling claimed this task.
hashar added a subscriber: hashar.Jul 31 2019, 5:19 AM

For the record, we frequently hit the issue of corrupted objects when unserializing from a different class signature. Even so that the exact same issue with ParserOutput and has hit us in September 2018 - T203566

T156541: BagOStuff should detect obsolete serialization or an unserialization resulting in a "wrong" object might be a solution.

[…] maybe somehow causes this to set $this->{""} with $this->$field.

Even a private static variable accessed with self:: may not exist? […] And even if it were null, you still wouldn't end up with $field = ''.

Afaik null can cast to empty string. But indeed, if the entire list were null, then foreach wouldn't iterate (and warn) and thus never trigger the presumed-faulty assignment.

Change 526555 abandoned by Krinkle:
Revert "objectcache: add MediumSpecificBagOStuff base class for non-proxy subclasses"

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

tstarling reopened this task as Open.Aug 1 2019, 12:02 AM
tstarling lowered the priority of this task from Unbreak Now! to Normal.

There are more log entries now from mediawikiwiki. Inspecting them in eval.php shows that they are due to cache entries saved before the fix was deployed. They have ParserOutput::$speculativeRevIdUsed as the unknown private member. Reducing priority since there is no new parser cache corruption and no user-visible impact.

I'll upload a hack which will suppress the notice. It's reasonable for the developer to expect that newly-defined fields will be null for unserialized objects that lack them, and that fields that have been removed from the class definition and are not otherwise referenced will not cause any problems. That's how it should be if the notice is suppressed.

I am making the assumption at this point that this one is safe to remove from train blockers, given likely volume of errors / impending hack. Please correct if I'm mistaken.

Change 526811 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/core@master] Suppress notice from ParserOutput::__sleep()

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

Change 526811 merged by jenkins-bot:
[mediawiki/core@master] Suppress notice from ParserOutput::__sleep()

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

Krinkle moved this task from Inbox to Radar on the Performance-Team board.Aug 1 2019, 6:31 PM
Krinkle edited projects, added Performance-Team (Radar); removed Performance-Team.
Krinkle moved this task from Limbo to Watching on the Performance-Team (Radar) board.
mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:06 PM