That would happen when array_keys doesn't return an array. Which to my knowledge can only happen if $this->mWrapperDivClasses is not an array. And I don't see how that can happen. Any ideas?

I could of course make a patch to protect against this failure, but that only hides the original error. I'd much rather find and fix that...

I had thought that unserializing a ParserOutput that had been cached under wmf.19 (before the field existed) would result in the field not being initialized and therefore being null, but it looks like it is initialized by the default on line 218 after all (at least when coming from the parser cache).

hphpd> $t = 'File:Nuvola Red Plus.svg'; $po = ParserCache::singleton()->get( Article::newFromTitle( Title::newFromText( $t ), RequestContext::getMain() ), ParserOptions::newCanonical() ); var_dump( $po );
$t = 'File:Nuvola Red Plus.svg'; $po = ParserCache::singleton()->get( Article::newFromTitle( Title::newFromText( $t ), RequestContext::getMain() ), ParserOptions::newCanonical() ); var_dump( $po );
object(ParserOutput)#758 (43) {
[...]
  ["mWrapperDivClasses":"ParserOutput":private]=>
  array(0) {
  }
[...]
}

https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2018.09.05/mediawiki?id=AWWp8zHxo1GdFyIEFnBZ&_g=h@44136fa seems to be the same error logged with a stack trace:

#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php(428): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php(314): ParserOutput->getWrapperDivClass()
#2 /srv/mediawiki/php-1.32.0-wmf.20/includes/OutputPage.php(1851): ParserOutput->getText(array)
#3 /srv/mediawiki/php-1.32.0-wmf.20/includes/OutputPage.php(1866): OutputPage->addParserOutputText(ParserOutput, array)
#4 /srv/mediawiki/php-1.32.0-wmf.20/includes/page/Article.php(559): OutputPage->addParserOutput(ParserOutput, array)
#5 /srv/mediawiki/php-1.32.0-wmf.20/includes/actions/ViewAction.php(68): Article->view()
#6 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(501): ViewAction->show()
#7 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(294): MediaWiki->performAction(Article, Title)
#8 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(868): MediaWiki->performRequest()
#9 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(525): MediaWiki->main()
#10 /srv/mediawiki/php-1.32.0-wmf.20/index.php(42): MediaWiki->run()
#11 /srv/mediawiki/w/index.php(3): include(string)
#12 {main}

In that code path the ParserOutput object is coming from ParserCache (Article.php line 550).

Fetching the ParserCache entry for the associated page with canonical parser options does give back a ParserOutput with mWrapperDivClasses set to null. Looking in the database backing the SqlBagOStuff, I find that the saved serialized ParserOutput object does explicitly have mWrapperDivClasses and it's set to null.

It's suggestive that this particular PO has a cache time of 2018-09-05 13:07:04, and wmf.20 was deployed to group1 at 13:07–13:08 according to https://wikitech.wikimedia.org/wiki/Server_Admin_Log#2018-09-05.

https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2018.09.05/mediawiki/?id=AWWp2NzQtaUawe_Stepy is another example. Same situation, including the cache time of 2018-09-05 13:07:02.

And https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2018.09.05/mediawiki?id=AWWp2AuDo1GdFyIEELbI&_g=h@44136fa with a cache time of 2018-09-05 13:07:01.

I have rolled the train and only a few occurences happened after ~ 4 minutes:

 182 Warning: Invalid operand type was used: implode() expects a container as one of the arguments in /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php on line 428
181 Warning: array_keys() expects parameter 1 to be an array or collection in /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php on line 428

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.

For this particular change, tests indicate that unserializing an old ParserOutput object will use the default value from the field's initializer, which is the empty array rather than null. Which doesn't cause the log messages seen here.

Every case I examined had the new field included in the serialized data, but with the value inexplicably null rather than an array. And every case had a parse time that coincided with the change from wmf.19 to wmf.20, I didn't see any that were after the move to wmf.20 was complete. If that continues to hold true, it could be some weirdness with running in a mixed environment.

tests indicate that unserializing an old ParserOutput object will use the default value from the field's initializer, which is the empty array rather than null.

Maybe that's broken in HHVM?

btw, I just realized that getText( ['unwrap'] ) will not work with "old" cached ParserOutput,

In T203567#4563613, @daniel wrote:

btw, I just realized that getText( ['unwrap'] ) will not work with "old" cached ParserOutput,

That's T203716: Duplicate mw-parser-output elements in action=parse API output.

In T203567#4563595, @daniel wrote:

tests indicate that unserializing an old ParserOutput object will use the default value from the field's initializer, which is the empty array rather than null.

Maybe that's broken in HHVM?

T156541 is the reference bug and there are more explanations on the duplicate bug, specially T156364#2977719 and below. And eventually some explanation of HHVM vs Zend behavior: https://github.com/facebook/hhvm/issues/7629 and https://3v4l.org/jrmrO

It is really an edge case.

Probably this will result in getWrapperDivClass() returning null (which gets type-juggled into empty string), right? So this would break TemplateStyles, which would be an UBN issue with the ongoing Wiki Loves Monuments campaign heavily relying on it.
Then again, if it only affected pages for a minute, that can't be too much of a deal. Can we get a list of affected pages and purge them? (Although we might want to wait for T203716 to be fixed first.)

Probably this will result in getWrapperDivClass() returning null (which gets type-juggled into empty string), right? So this would break TemplateStyles, which would be an UBN issue with the ongoing Wiki Loves Monuments campaign heavily relying on it.

It would cause getWrapperDivClass() tor return null on ParserOutput instances generated by old code. That old code also put the wrapper around the HTML before passing it into ParserOutput, which would prevent doubt-wrapping for cases that did nto need unwrapping before.

Then again, if it only affected pages for a minute, that can't be too much of a deal.

The parser cache expery is set ot 22 days according to https://phabricator.wikimedia.org/source/mediawiki-config/browse/master/wmf-config/InitialiseSettings.php$12129. And changing it does no good, since the expiry time is set when writing the cache entry.

We could however bump Parser::VERSION. The change to the output is rather minor, but Parser::VERSION is designed too handle exactly this situation: to ignore ParserCache entries generated by an old version of the parser.

Can we get a list of affected pages and purge them?

As far as I can see, it affects all ParserCache entries generated before the new code was deployed. But the effect would only be visible in ApiMobileView.

One option would be to put the old behavior of the unwrap back for now. That would be an easy fix, though we'd want to make sure we remember to remove it eventually.

In T203567#4565582, @daniel wrote:

One option would be to put the old behavior of the unwrap back for now. That would be an easy fix, though we'd want to make sure we remember to remove it eventually.

Oh, I see @Tgr did that in https://gerrit.wikimedia.org/r/c/mediawiki/core/+/458732. Thanks!

So, do we live with the warning and use it to allow us to known whether there are still old entries in the cache? Or should I write a patch that avoid the warning?

There isn't any guarantee the warning happens for old entries; per @Anomie, it seems to only happen with mixed code (ie. during scap was running and PHP files had a version mismatch or something like that). Here's a list of the top 50 URLs from logstash:

I think I figured out what's causing this. Details in T203566#4566713, the short version is that a PO serialized in wmf.20 gets corrupted if it's unserialized and re-serialized in wmf.19 with HHVM.

I'm not sure why the PO is being unserialized and re-serialized in wmf.19 in the first place, whether that's existing behavior or something new in DerivedPageDataUpdater.

In T203567#4559481, @daniel wrote:

That would happen when array_keys doesn't return an array. Which to my knowledge can only happen if $this->mWrapperDivClasses is not an array.

And indeed, the logs also contain:

PHP Warning: array_keys() expects parameter 1 to be an array or collection

#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php(428): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.32.0-wmf.20/includes/parser/ParserOutput.php(314): ParserOutput->getWrapperDivClass()
#2 /srv/mediawiki/php-1.32.0-wmf.20/includes/OutputPage.php(1851): ParserOutput->getText(array)
#3 /srv/mediawiki/php-1.32.0-wmf.20/includes/OutputPage.php(1866): OutputPage->addParserOutputText(ParserOutput, array)
#4 /srv/mediawiki/php-1.32.0-wmf.20/extensions/FlaggedRevs/frontend/FlaggablePageView.php(765): OutputPage->addParserOutput(ParserOutput, array)
#5 /srv/mediawiki/php-1.32.0-wmf.20/extensions/FlaggedRevs/frontend/FlaggablePageView.php(391): FlaggablePageView->showStableVersion(FlaggedRevision, string, string)
#6 /srv/mediawiki/php-1.32.0-wmf.20/extensions/FlaggedRevs/frontend/FlaggedRevsUI.hooks.php(204): FlaggablePageView->setPageContent(boolean, boolean)
#7 /srv/mediawiki/php-1.32.0-wmf.20/includes/Hooks.php(174): FlaggedRevsUIHooks::onArticleViewHeader(Article, boolean, boolean)
#8 /srv/mediawiki/php-1.32.0-wmf.20/includes/Hooks.php(202): Hooks::callHook(string, array, array, NULL)
#9 /srv/mediawiki/php-1.32.0-wmf.20/includes/page/Article.php(537): Hooks::run(string, array)
#10 /srv/mediawiki/php-1.32.0-wmf.20/includes/actions/ViewAction.php(68): Article->view()
#11 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWiki.php(501): ViewAction->show()

I won't file a new task though, given they are caused by the same cache-compatibility issue.

https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/458726/

The error here shouldn't be logged again unless we try to roll back to wmf.19 again.

The mWrapperDivClasses errors from this task are still happening on wmf.20. Logstash records 5,300 hits in the last 24 hours, including in the current hour.

From IRC:
<DanielK_WMDE_> is there anything we can do about this right now?
<anomie> Purge any affected pages to clear the corrupted PO from the parser cache.