Page MenuHomePhabricator

ParserOutput cache incompatibility errors in 1.32.0-wmf.20
Closed, ResolvedPublicPRODUCTION ERROR

Description

Compatibility errors:

  1. PHP Notice: serialize() '' returned as member variable from __sleep() but does not exist – this task.
  2. PHP Warning: Invalid operand type was used: implode() expects a container T203567
  3. PHP Warning: array_keys() expects parameter 1 to be an array or collection– also T203567.

sleep/serialize error

Spotted while deploying 1.32.0-wmf.20 to group1:

5 Notice: serialize(): "" returned as member variable from __sleep() but does not exist in /srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php on line 668
5 Notice: serialize(): "" returned as member variable from __sleep() but does not exist in /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php on line 225
5 Notice: serialize(): "" returned as member variable from __sleep() but does not exist

That might come from objects coming from the cache that do not match the object signature in the code?

Example with exception id W4-U9QpAAEIAADo3ElYAAAAN

PHP Notice: serialize(): "" returned as member variable from __sleep() but does not exist
#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.32.0-wmf.19/includes/libs/objectcache/MemcachedBagOStuff.php(65): Memcached->set(string, ParserOutput, integer)
#3 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MemcachedPeclBagOStuff.php(162): MemcachedBagOStuff->set(string, ParserOutput, integer)
#4 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php(232): MemcachedPeclBagOStuff->set(string, ParserOutput, integer)
#5 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php(139): MultiWriteBagOStuff->doWrite(array, boolean, string, string, ParserOutput, integer)
#6 /srv/mediawiki/php-1.32.0-wmf.19/includes/parser/ParserCache.php(336): MultiWriteBagOStuff->set(string, ParserOutput, integer)
#7 /srv/mediawiki/php-1.32.0-wmf.19/includes/Storage/DerivedPageDataUpdater.php(1402): ParserCache->save(ParserOutput, WikiPage, ParserOptions, string, integer)
#8 /srv/mediawiki/php-1.32.0-wmf.19/includes/Storage/PageUpdater.php(1199): MediaWiki\Storage\DerivedPageDataUpdater->doUpdates()
#9 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/Database.php(3746): Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate(Wikimedia\Rdbms\DatabaseMysqli, string)
#10 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/DBConnRef.php(49): Wikimedia\Rdbms\Database->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;1380)
#11 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/DBConnRef.php(529): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#12 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/AtomicSectionUpdate.php(35): Wikimedia\Rdbms\DBConnRef->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;1380)
#13 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(268): AtomicSectionUpdate->doUpdate()
#14 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate(AtomicSectionUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer)
#15 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(130): DeferredUpdates::execute(array, string, integer)
#16 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(607): DeferredUpdates::doUpdates(string, integer)
#17 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(576): MediaWiki::preOutputCommit(RequestContext, Closure$MediaWiki::main;343)
#18 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(884): MediaWiki->doPreOutputCommit(Closure$MediaWiki::main;343)
#19 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(525): MediaWiki->main()
#20 /srv/mediawiki/php-1.32.0-wmf.19/index.php(42): MediaWiki->run()
#21 /srv/mediawiki/w/index.php(3): include(string)
#22 {main}
PHP Notice: serialize(): "" returned as member variable from __sleep() but does not exist
/srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php:225
#0 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php(225): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php(139): MultiWriteBagOStuff->doWrite(array, boolean, string, string, ParserOutput, integer)
#2 /srv/mediawiki/php-1.32.0-wmf.19/includes/parser/ParserCache.php(336): MultiWriteBagOStuff->set(string, ParserOutput, integer)
#3 /srv/mediawiki/php-1.32.0-wmf.19/includes/Storage/DerivedPageDataUpdater.php(1402): ParserCache->save(ParserOutput, WikiPage, ParserOptions, string, integer)
#4 /srv/mediawiki/php-1.32.0-wmf.19/includes/Storage/PageUpdater.php(1199): MediaWiki\Storage\DerivedPageDataUpdater->doUpdates()
#5 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/Database.php(3746): Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate(Wikimedia\Rdbms\DatabaseMysqli, string)
#6 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/DBConnRef.php(49): Wikimedia\Rdbms\Database->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;1380)
#7 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/rdbms/database/DBConnRef.php(529): Wikimedia\Rdbms\DBConnRef->__call(string, array)
#8 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/AtomicSectionUpdate.php(35): Wikimedia\Rdbms\DBConnRef->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;1380)
#9 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(268): AtomicSectionUpdate->doUpdate()
#10 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate(AtomicSectionUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer)
#11 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(130): DeferredUpdates::execute(array, string, integer)
#12 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(607): DeferredUpdates::doUpdates(string, integer)
#13 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(576): MediaWiki::preOutputCommit(RequestContext, Closure$MediaWiki::main;343)
#14 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(884): MediaWiki->doPreOutputCommit(Closure$MediaWiki::main;343)
#15 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(525): MediaWiki->main()
#16 /srv/mediawiki/php-1.32.0-wmf.19/index.php(42): MediaWiki->run()
#17 /srv/mediawiki/w/index.php(3): include(string)
#18 {main}
/srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php:668
PHP Notice: serialize(): "" returned as member variable from __sleep() but does not exist
#0 /srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php(668): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php(351): SqlBagOStuff->serialize(ParserOutput)
#2 /srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php(376): SqlBagOStuff->setMulti(array, integer)
#3 /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php(240): SqlBagOStuff->set(string, ParserOutput, integer)
#4 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/MWCallableUpdate.php(34): Closure$MultiWriteBagOStuff::doWrite()
#5 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(268): MWCallableUpdate->doUpdate()
#6 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate(MWCallableUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer)
#7 /srv/mediawiki/php-1.32.0-wmf.19/includes/deferred/DeferredUpdates.php(134): DeferredUpdates::execute(array, string, integer)
#8 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(914): DeferredUpdates::doUpdates(string)
#9 /srv/mediawiki/php-1.32.0-wmf.19/includes/MediaWiki.php(734): MediaWiki->restInPeace(string, boolean)
#10 [internal function]: Closure$MediaWiki::doPostOutputShutdown()
#11 {main}

Related Objects

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes

Ditto when promoting all wikis:

84 Notice: serialize(): "" returned as member variable from __sleep() but does not exist in /srv/mediawiki/php-1.32.0-wmf.19/includes/libs/objectcache/MultiWriteBagOStuff.php on line 225
84 Notice: serialize(): "" returned as member variable from __sleep() but does not exist
84 Notice: serialize(): "" returned as member variable from __sleep() but does not exist in /srv/mediawiki/php-1.32.0-wmf.19/includes/objectcache/SqlBagOStuff.php on line 668

That might be related to T156541: BagOStuff should detect obsolete serialization or an unserialization resulting in a "wrong" object. The cache has a serialized object of a class at version n-1 and that has some side effects when unserializing to the class of version n.

That is a dupe of T156541 which has a nice description about serialize / unserialize when the class has changed.

Krinkle added a subscriber: Krinkle.

@hashar There is not going to be a way to automatically make breaking changes not break. I believe task T156541 would be resolved by detecting this breaking change in CI to prevent it from causing issues in production.

However, this task is about such issue having happened in a specific class (ParserOutput) and that probably does still need to be fixed, because we intend to be compatible with multiversion deployments. One of the servers can always get a newer version, and likewise, the cache will hold old versions.

It is a bug that ParserOutput was changed in a seemingly breaking way without ensuring that a different cache key is used, and without ensuring the difference is detected by other means. This is an open issue and still needs to be fixed.

Krinkle renamed this task from Notice: serialize(): "" returned as member variable from __sleep() but does not exist to ParserOutput cache incompatibility ("PHP Notice: serialize() '' returned as member variable from __sleep() but does not exist).Sep 6 2018, 9:24 PM
Krinkle moved this task from Library to ParserCache on the MediaWiki-libs-ObjectCache board.
Krinkle triaged this task as Unbreak Now! priority.Sep 6 2018, 9:27 PM

Due to PHP Notices not being fatal, execution continues in a less-than-predictable way without the code having explicitly accounted for this happening. It is currently unknown what the impact of this cache-incompatible change is.

It is possible that the field's absence is gracefully backfilled when it finds it absence. It is possible that the caller validates the object and discards the cache entry. Those would both be good outcomes. It is also possible that it continues without knowing (which is much more likely, given the PHP Notice) in which case other code may be making wrong assumptions about the page in question and cause cascading failures elsewhere that are much harder to detect.

While that is a possibility for most PHP Notices, it tends to not matter as much in UI code given it's easy to fix afterwards with limited impact. But given Parser, making UBN.

I don't see the relationship to T156541. That one is about changing the visibility of a property, which results in PHP ending up with two seemingly identically named properties. This one is about __sleep() (and, ultimately, get_object_vars()) returning the empty string as a property name (assuming the error message is reliable).

This seems pretty harmless apart from the logspam - serialization will still work (https://3v4l.org/9KgXc), the class will end up with a weirdly named variable set to NULL but I can't see that being a problem. (I tried filtering in __wakeup() but that doesn't work: https://3v4l.org/9KgXc)

Note that (presumably) the same class definition change also caused T203716: Duplicate mw-parser-output elements in action=parse API output, which might well be an UBN issue.

Change 458726 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@master] Prevent ParserOutput::__sleep() from returning empty variable names

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

If the warning is itself a problem, the above patch should fix it (probably - I have no idea how to reproduce the error) and it also avoids creating the unnamed property. I have no clue about the root issue, I can only assume it's some kind of PHP bug. Maybe someone with more PHP internals knowledge (@Smalyshev? @Anomie?) has an idea.

It is a bug that ParserOutput was changed in a seemingly breaking way without ensuring that a different cache key is used, and without ensuring the difference is detected by other means. This is an open issue and still needs to be fixed.

Forcing a different cache key to be used is equivalent to bumping Parser::VERSION, and would likely bring down the cluster. See T203781: Allow Parser::VERSION to be bumped without immediately resetting the ParserCache for an idea.

Ok, I think I figured out what's going on both here and in T203567.

I tested this with a simplified class. The equivalent to wmf.20 looks like this:

class MyObj {
	private $skip = "from new version";
	private $oldField = "from new version";
	private $newField = "from new version";

	public function __sleep() {
		return array_diff(
			array_keys( get_object_vars( $this ) ),
			[ 'skip' ]
		);
	}
}

The equivalent to wmf.19 lacks $newField, and changes the default values of the strings.

All these tests were run on mwmaint1001 using HHVM 3.18.6-dev.

When wmf.19 unserializes a ParserOutput object that was serialized from wmf.20, it creates a sane-looking object:

object(MyObj)#1 (3) {
  ["skip":"MyObj":private]=>
  string(16) "from old version"
  ["oldField":"MyObj":private]=>
  string(16) "from new version"
  ["newField":"MyObj":private]=>
  string(16) "from new version"
}

The problem happens when you try to re-serialize that object. __sleep() returns the NUL-containing default representation of $newField instead of just "newField" as expected:

array(2) {
  [1]=>
  string(8) "oldField"
  [2]=>
  string(15) "\0MyObj\0newField"
}

When serialize() outputs the warning, C's printf() truncates the value at the first NUL byte, so it looks like it's complaining about the empty string instead of the actual bad value. Then serialize() goes ahead and tries to output the value of a public field named "\0MyObj\0newField" rather than the private field:

[Fri Sep  7 15:09:24 2018] [hphp] [12043:7ffbecdbf3c0:0:000001] [] 
Notice: serialize(): "" returned as member variable from __sleep() but does not exist in /home/anomie/tmp/weirdSerialization/oldstyle.php on line 39
O:5:"MyObj":2:{s:15:"\0MyObj\0oldField";s:16:"from new version";s:15:"\0MyObj\0newField";N;}

Of course, since that's exactly the syntax for a private field named $newField, when it gets unserialized in the future (by wmf.19 or wmf.20) it reads $newField in as null, causing T203567.

Using PHP 7.0.30-0+deb9u1 on mwmaint1001, BTW, it works fine (but loses data). There __sleep() doesn't return the bogus "\0MyObj\0newField" in the first place.

Note this only happens with the __sleep() method. With no __sleep() both HHVM and PHP 7.0 re-serialize the object with the same representation as was input.

If we force __sleep() to return "newField" (instead of HHVM's "\0MyObj\0newField" or PHP 7.0's omission of it altogether), PHP 7.0 works fine (without data loss) while HHVM still misbehaves:

[Fri Sep  7 15:31:06 2018] [hphp] [19251:7f79a0cc63c0:0:000001] [] 
Notice: serialize(): "newField" returned as member variable from __sleep() but does not exist in /home/anomie/tmp/weirdSerialization/oldstyle.php on line 40
O:5:"MyObj":2:{s:15:"\0MyObj\0oldField";s:16:"from new version";s:8:"newField";N;}
Krinkle renamed this task from ParserOutput cache incompatibility ("PHP Notice: serialize() '' returned as member variable from __sleep() but does not exist) to ParserOutput cache incompatibility errors in 1.32.0-wmf.20.Sep 8 2018, 4:27 AM
Krinkle updated the task description. (Show Details)
Krinkle updated the task description. (Show Details)

Summary of the situation: ParserOutput objects that were created under wmf.20 and then re-serialized under wmf.19 are affected. I don't know of any ongoing creation of new affected POs. Any affected page can be purged to refresh the parser cache and clear the affected objects. If identifying those from the log messages is too difficult, we might also use the 'RejectParserCacheValue' hook to reject ParserOutput objects that were generated at about the time that we did the wmf.19→20 train each day.

Longer term, there's some talk about replacing the serialization logic with something more explicit, in the hope that it will encourage coders to more carefully consider this sort of thing when making changes to ParserOutput. Switching the parser cache to JSON has been mentioned, and/or we could use PHP's Serializable interface as a step along that path.

All bad cache entries should have expired by now. There seems to be nothing to do here other than changing the ParserCache to using JSON. Can this be closed?

Change 458726 abandoned by Gergő Tisza:
Prevent ParserOutput::__sleep() from returning empty variable names

Reason:
Using JSON serialization is a saner approach. Old entries have expired so there is no time pressure now.

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

All bad cache entries should have expired by now. There seems to be nothing to do here other than changing the ParserCache to using JSON. Can this be closed?

Is that part tracked somewhere?

Krinkle lowered the priority of this task from Unbreak Now! to High.Oct 10 2018, 8:57 PM
Krinkle removed a project: Patch-For-Review.
CCicalese_WMF lowered the priority of this task from High to Medium.Oct 15 2018, 3:10 PM
CCicalese_WMF added a subscriber: CCicalese_WMF.

The production errors are addressed, but we need to make a decision on long term architecture to prevent this from being an issue again in the future.

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:09 PM