Page MenuHomePhabricator

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
Closed, DuplicatePublic

Description

In the hhvm log bucket there are a couple of related errors:

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
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

They are coming from:

includes/parser/ParserOutput.php
420     /**
421      * Returns the class (or classes) to be used with the wrapper div for this otuput.
422      * If there is no wrapper class given, no wrapper div should be added.
423      * The wrapper div is added automatically by getText().
424      *
425      * @return string
426      */
427     public function getWrapperDivClass() {
428         return implode( ' ', array_keys( $this->mWrapperDivClasses ) );
429     }
430

Apparently introduced in 0dc7ba02b4483700a2fc3ab6bf76a3dd072ef054 https://gerrit.wikimedia.org/r/c/mediawiki/core/+/455865

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 5 2018, 1:16 PM
hashar updated the task description. (Show Details)Sep 5 2018, 1:17 PM
daniel added a comment.Sep 5 2018, 1:21 PM

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...

Anomie claimed this task.Sep 5 2018, 1:26 PM

I see what's going on here. Patch incoming once I finish testing.

Anomie removed Anomie as the assignee of this task.Sep 5 2018, 1:45 PM

I was wrong, can't reproduce as I thought.

Anomie added a comment.Sep 5 2018, 1:52 PM

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) {
  }
[...]
}
Anomie added a comment.Sep 5 2018, 2:24 PM

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.

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.

Anomie added a comment.Sep 6 2018, 2:06 PM

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.

daniel added a comment.Sep 6 2018, 4:49 PM

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?

daniel added a comment.Sep 6 2018, 4:51 PM

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

Tgr added a comment.Sep 6 2018, 9:23 PM

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.

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.

Tgr added a comment.Sep 7 2018, 8:37 AM

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.)

daniel added a comment.Sep 7 2018, 9:36 AM

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.

daniel added a comment.Sep 7 2018, 9:43 AM

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!

daniel added a comment.Sep 7 2018, 9:44 AM

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?

Tgr added a comment.Sep 7 2018, 10:24 AM

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:


the number or affected pages seems tiny (maybe a few dozen), purging them by hand should not be too hard.

Anomie added a comment.Sep 7 2018, 3:28 PM

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.

Krinkle triaged this task as High priority.Sep 8 2018, 4:26 AM
Krinkle added a subscriber: Krinkle.

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
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/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.

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.

It looks like T203566: ParserOutput cache incompatibility errors in 1.32.0-wmf.20 has been broadened so this is now a duplicate of that task. Closing as such.

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