Page MenuHomePhabricator
Create Task
Maniphest T313341

PHP Notice: Undefined property: Wikimedia\PSquare::$increments
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error
normalized_message
[{reqId}] {exception_url}   PHP Notice: Undefined property: Wikimedia\PSquare::$increments
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.19/vendor/wikimedia/running-stat/src/Wikimedia/PSquare.php(110)
#0 /srv/mediawiki/php-1.39.0-wmf.19/vendor/wikimedia/running-stat/src/Wikimedia/PSquare.php(110): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.39.0-wmf.19/extensions/Scribunto/includes/Hooks.php(238): Wikimedia\PSquare->addObservation(integer)
#2 /srv/mediawiki/php-1.39.0-wmf.19/extensions/Scribunto/includes/Hooks.php(154): MediaWiki\Extension\Scribunto\Hooks::reportTiming(string, string, integer)
#3 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(3453): MediaWiki\Extension\Scribunto\Hooks::invokeHook(Parser, PPTemplateFrame_Hash, array)
#4 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(3136): Parser->callParserFunction(PPTemplateFrame_Hash, string, array)
#5 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/PPFrame_Hash.php(276): Parser->braceSubstitution(array, PPTemplateFrame_Hash)
#6 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(3327): PPFrame_Hash->expand(PPNode_Hash_Tree)
#7 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/PPFrame_Hash.php(276): Parser->braceSubstitution(array, PPFrame_Hash)
#8 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(2971): PPFrame_Hash->expand(PPNode_Hash_Tree, integer)
#9 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(1607): Parser->replaceVariables(string)
#10 /srv/mediawiki/php-1.39.0-wmf.19/includes/parser/Parser.php(723): Parser->internalParse(string)
#11 /srv/mediawiki/php-1.39.0-wmf.19/includes/content/WikitextContentHandler.php(295): Parser->parse(string, Title, ParserOptions, boolean, boolean, integer)
#12 /srv/mediawiki/php-1.39.0-wmf.19/includes/content/ContentHandler.php(1703): WikitextContentHandler->fillParserOutput(WikitextContent, MediaWiki\Content\Renderer\ContentParseParams, ParserOutput)
#13 /srv/mediawiki/php-1.39.0-wmf.19/includes/content/Renderer/ContentRenderer.php(47): ContentHandler->getParserOutput(WikitextContent, MediaWiki\Content\Renderer\ContentParseParams)
#14 /srv/mediawiki/php-1.39.0-wmf.19/includes/Revision/RenderedRevision.php(270): MediaWiki\Content\Renderer\ContentRenderer->getParserOutput(WikitextContent, Title, integer, ParserOptions, boolean)
#15 /srv/mediawiki/php-1.39.0-wmf.19/includes/Revision/RenderedRevision.php(237): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached(WikitextContent, boolean)
#16 /srv/mediawiki/php-1.39.0-wmf.19/includes/Revision/RevisionRenderer.php(236): MediaWiki\Revision\RenderedRevision->getSlotParserOutput(string, array)
#17 /srv/mediawiki/php-1.39.0-wmf.19/includes/Revision/RevisionRenderer.php(158): MediaWiki\Revision\RevisionRenderer->combineSlotOutput(MediaWiki\Revision\RenderedRevision, array)
#18 [internal function]: MediaWiki\Revision\RevisionRenderer->MediaWiki\Revision\{closure}(MediaWiki\Revision\RenderedRevision, array)
#19 /srv/mediawiki/php-1.39.0-wmf.19/includes/Revision/RenderedRevision.php(199): call_user_func(Closure, MediaWiki\Revision\RenderedRevision, array)
#20 /srv/mediawiki/php-1.39.0-wmf.19/includes/poolcounter/PoolWorkArticleView.php(91): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#21 /srv/mediawiki/php-1.39.0-wmf.19/includes/poolcounter/PoolWorkArticleViewCurrent.php(97): PoolWorkArticleView->renderRevision()
#22 /srv/mediawiki/php-1.39.0-wmf.19/includes/poolcounter/PoolCounterWork.php(162): PoolWorkArticleViewCurrent->doWork()
#23 /srv/mediawiki/php-1.39.0-wmf.19/includes/page/ParserOutputAccess.php(299): PoolCounterWork->execute()
#24 /srv/mediawiki/php-1.39.0-wmf.19/includes/page/Article.php(705): MediaWiki\Page\ParserOutputAccess->getParserOutput(WikiFilePage, ParserOptions, MediaWiki\Revision\RevisionStoreCacheRecord, integer)
#25 /srv/mediawiki/php-1.39.0-wmf.19/includes/page/Article.php(517): Article->generateContentOutput(User, ParserOptions, integer, OutputPage, array)
#26 /srv/mediawiki/php-1.39.0-wmf.19/includes/page/ImagePage.php(95): Article->view()
#27 /srv/mediawiki/php-1.39.0-wmf.19/includes/page/Article.php(1808): ImagePage->view()
#28 /srv/mediawiki/php-1.39.0-wmf.19/includes/actions/RenderAction.php(39): Article->render()
#29 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(549): RenderAction->show()
#30 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(322): MediaWiki->performAction(ImagePage, Title)
#31 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(913): MediaWiki->performRequest()
#32 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(569): MediaWiki->main()
#33 /srv/mediawiki/php-1.39.0-wmf.19/index.php(50): MediaWiki->run()
#34 /srv/mediawiki/php-1.39.0-wmf.19/index.php(46): wfIndexMain()
#35 /srv/mediawiki/w/index.php(3): require(string)
#36 {main}
Impact

90000 errors in the last 15 minutes, making logspam-watch completely unusable. These errors started around 2022/07/19 17:00 UTC and are coming in at a rate of about 30K every 5 minutes.

Notes

Details

Request URL
https://commons.wikimedia.org/w/index.php?title=*&action=render&uselang=*
SubjectRepoBranchLines +/-
Bump scribunto-stats cache versionmediawiki/extensions/Scribuntowmf/1.39.0-wmf.25+1 -1
Bump scribunto-stats cache versionmediawiki/extensions/Scribuntomaster+1 -1
build: Update wikimedia/running-stat to 2.1.0mediawiki/coremaster+2 -2
PSquare: Implement `__serialize()` and `__unserialize()`RunningStatmaster+75 -11
Hooks: Bump scribunto-stats cache versionmediawiki/extensions/Scribuntowmf/1.39.0-wmf.21+2 -2
Hooks: Minor clean up, remove redundant PSquare checkmediawiki/extensions/Scribuntomaster+2 -4
Hooks: Bump scribunto-stats cache versionmediawiki/extensions/Scribuntomaster+2 -2
Customize query in gerrit

Related Objects
Search...

StatusSubtypeAssignedTask
 ResolvedReleasejeenaT308074 1.39.0-wmf.21 deployment blockers
 ResolvedPRODUCTION ERRORKrinkleT313341 PHP Notice: Undefined property: Wikimedia\PSquare::$increments

Event Timeline

jeena triaged this task as Unbreak Now! priority.Jul 19 2022, 6:24 PM
jeena created this task.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 19 2022, 6:24 PM
jeena added a parent task: T308074: 1.39.0-wmf.21 deployment blockers.Jul 19 2022, 6:25 PM
dancy subscribed.Jul 19 2022, 6:27 PM
Agusbou2015 subscribed.Jul 19 2022, 6:28 PM
dancy updated the task description. (Show Details)Jul 19 2022, 6:33 PM
dancy updated the task description. (Show Details)
brennen added subscribers: Reedy, brennen.Jul 19 2022, 6:42 PM

Hmm:

18:42:01 brennen@deploy1002 /srv/mediawiki-staging/php-1.39.0-wmf.21/vendor/wikimedia/running-stat/src ((7fa1a1aa...)) $ git log PSquare.php
commit 2e6f56ed400e8933b5b069ad5224f19881cdd359
Author: Reedy <reedy@wikimedia.org>
Date:   Fri Jul 8 23:39:31 2022 +0100

    Upgrading wikimedia/running-stat (v1.2.1 => v2.0.0)
    
    Change-Id: I353c10547d7161caaba246f169adfa91a4a6cd77

@Reedy any thoughts here?

brennen added a project: MediaWiki-libs-RunningStat.Jul 19 2022, 6:43 PM
Restricted Application added a project: Performance-Team. · View Herald TranscriptJul 19 2022, 6:43 PM
Zabe subscribed.Jul 19 2022, 6:44 PM
Zabe added a comment.Jul 19 2022, 6:46 PM

It's very interesting that the error is in wmf.19. The missing var was added in https://gerrit.wikimedia.org/r/c/RunningStat/+/770650, but it never caused issues. But now that the new var is available in wmf.21, it starts throwing fatals in wmf.19.

Zabe moved this task from Untriaged to Jul 2022 on the Wikimedia-production-error board.Jul 19 2022, 6:58 PM
Krinkle subscribed.Jul 19 2022, 7:34 PM

The stack trace shows that the code creating and interacting with this PSquare object, is the Scribunto extension.

Specifically, here: Scribunto/Hooks.php L217

Scribunto/Hooks.php
$cache = ObjectCache::getLocalServerInstance( .. );
$ps = $cache->get( $key ) ?: new PSquare( $threshold );
$ps->addObservation( $timing );
$cache->set( $key, $ps, 60 );

With the knowledge now that the object is serialised/persisted/unserialized via php-apcu (the "local server cache"), it seems most likely that this object is being shared between wikis and thus between MW versions.

And so given that wmf.19 was fine when it was the only deployed version, and given that wmf.21 appears fine within itself, and given the error is coming from a wmf.19-served request, I believe the scenario we're seeing is a PSquare object created during a wmf.21 request being interacted with from the cache by a wmf.19 request.

The change that was deployed in wmf.21 is to make the increments field private instead of (implicitly) created as a public field. Based on wmf.21 requests internally being fine, we can therefore emperically conclude that this change indeed is safe in so far that we do not have code that relied upon the fact that this field was implicitly public. The only access to this property we have in production is within the same class in addObservation using $this->increments which the unit tests as well as the wmf.21 servers indicate works fine.

Where it goes wrong is when we try to materialize (unserialize) the wmf.21 object in a process with the previous version of the PSquare class. It will be trying to bring to life an instance of the old class with the serialization data from a newer instance.

In other words:

// Request to wmf.21 server
class Foo {}
$x = new Foo();
$x->something = 42;
echo serialize($x); // store in cache

// Request to wmf.19 server
class Foo {
  private $something;
}
$x = unserialize($cacheSer);

We can see what the serialization looks like by runnig the above in an eval https://3v4l.org/fCs2s:

# serialize:
O:3:"Foo":1:{s:5:"stuff";a:1:{i:0;i:42;}}

# visualisation via var_dump:
object(Foo)#1 (1) {
  ["stuff"]=>
  array(1) {
    [0]=>
    int(42)
  }
}


# serialize:
O:3:"Bar":1:{s:10:"Barstuff";a:1:{i:0;i:42;}}

# visualisation via var_dump:
object(Bar)#2 (1) {
  ["stuff":"Bar":private]=>
  array(1) {
    [0]=>
    int(42)
  }
}

The serialization format is different for private fields as for public fields, so I assume the serialised data for this unknown "Psquareincrements" field is simply ignored, and the previously public implicitly-created increments field remains not-yet-created, and thus we get an error. Normally this gets created by the constructor, but the constructor only runs when creating new objects, not when re-materialising an already existing object.

TheresNoTime subscribed.Jul 19 2022, 7:36 PM
Krinkle claimed this task.Jul 19 2022, 7:37 PM
RhinosF1 subscribed.Jul 19 2022, 7:52 PM
gerritbot added a comment.Jul 19 2022, 7:53 PM

Change 815373 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/extensions/Scribunto@master] Hooks: Bump scribunto-stats cache version

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

gerritbot added a project: Patch-For-Review.Jul 19 2022, 7:53 PM
gerritbot added a comment.Jul 19 2022, 8:02 PM

Change 815375 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/extensions/Scribunto@master] Hooks: Minor clean up, remove redundant PSquare check

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

gerritbot added a comment.Jul 19 2022, 8:16 PM

Change 815373 merged by jenkins-bot:

[mediawiki/extensions/Scribunto@master] Hooks: Bump scribunto-stats cache version

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

gerritbot added a comment.Jul 19 2022, 8:17 PM

Change 815281 had a related patch set uploaded (by Jforrester; author: Krinkle):

[mediawiki/extensions/Scribunto@wmf/1.39.0-wmf.21] Hooks: Bump scribunto-stats cache version

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

gerritbot added a comment.Jul 19 2022, 8:29 PM

Change 815375 merged by jenkins-bot:

[mediawiki/extensions/Scribunto@master] Hooks: Minor clean up, remove redundant PSquare check

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

gerritbot added a comment.Jul 19 2022, 8:35 PM

Change 815281 merged by jenkins-bot:

[mediawiki/extensions/Scribunto@wmf/1.39.0-wmf.21] Hooks: Bump scribunto-stats cache version

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

ReleaseTaggerBot added a project: MW-1.39-notes (1.39.0-wmf.22; 2022-07-25).Jul 19 2022, 9:00 PM
Stashbot added a comment.Jul 19 2022, 9:17 PM

Mentioned in SAL (#wikimedia-operations) [2022-07-19T21:17:55Z] <jforrester@deploy1002> Synchronized php-1.39.0-wmf.21/extensions/Scribunto/includes/Hooks.php: Train unblocker: [[gerrit:815281|Hooks: Bump scribunto-stats cache version (T313341)]] (duration: 03m 14s)

Jdforrester-WMF closed this task as Resolved.Jul 19 2022, 9:18 PM
Jdforrester-WMF subscribed.

Should be fixed.

Maintenance_bot removed a project: Patch-For-Review.Jul 19 2022, 9:30 PM
gerritbot added a comment.Jul 20 2022, 5:08 AM

Change 815429 had a related patch set uploaded (by Krinkle; author: Krinkle):

[RunningStat@master] PSquare: Implement `__serialize()` and `__unserialize()`

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

gerritbot added a project: Patch-For-Review.Jul 20 2022, 5:08 AM
gerritbot added a comment.Jul 20 2022, 12:58 PM

Change 815429 merged by jenkins-bot:

[RunningStat@master] PSquare: Implement `__serialize()` and `__unserialize()`

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

Maintenance_bot removed a project: Patch-For-Review.Jul 20 2022, 1:29 PM
Krinkle added a comment.Jul 29 2022, 4:37 AM
In T313341#8091082, @gerritbot wrote:

Change 815429 merged by jenkins-bot:

[RunningStat@master] PSquare: Implement `__serialize()` and `__unserialize()`

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

For the record - now released as wikimedia/running-stat 2.1.0.

gerritbot added a comment.Aug 3 2022, 5:54 AM

Change 818290 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] build: Update wikimedia/running-stat to 2.1.0

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

gerritbot added a project: Patch-For-Review.Aug 3 2022, 5:54 AM
gerritbot added a comment.Aug 3 2022, 2:03 PM

Change 818290 merged by jenkins-bot:

[mediawiki/core@master] build: Update wikimedia/running-stat to 2.1.0

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

Maintenance_bot removed a project: Patch-For-Review.Aug 3 2022, 2:30 PM
ReleaseTaggerBot edited projects, added MW-1.39-notes (1.39.0-wmf.25; 2022-08-15); removed MW-1.39-notes (1.39.0-wmf.22; 2022-07-25).Aug 3 2022, 3:00 PM
gerritbot added a comment.Aug 16 2022, 7:09 PM

Change 823710 had a related patch set uploaded (by Krinkle; author: Zabe):

[mediawiki/extensions/Scribunto@master] Bump scribunto-stats cache version

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

gerritbot added a project: Patch-For-Review.Aug 16 2022, 7:09 PM

Change 823634 had a related patch set uploaded (by Krinkle; author: Zabe):

[mediawiki/extensions/Scribunto@wmf/1.35.0-wmf.26] Bump scribunto-stats cache version

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

gerritbot added a comment.Aug 16 2022, 7:27 PM

Change 823710 merged by jenkins-bot:

[mediawiki/extensions/Scribunto@master] Bump scribunto-stats cache version

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

gerritbot added a comment.Aug 16 2022, 7:41 PM

Change 823635 had a related patch set uploaded (by Zabe; author: Zabe):

[mediawiki/extensions/Scribunto@wmf/1.39.0-wmf.25] Bump scribunto-stats cache version

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

ReleaseTaggerBot edited projects, added MW-1.39-notes (1.39.0-wmf.26; 2022-08-22); removed MW-1.39-notes (1.39.0-wmf.25; 2022-08-15).Aug 16 2022, 8:01 PM
gerritbot added a comment.Aug 16 2022, 8:14 PM

Change 823635 merged by jenkins-bot:

[mediawiki/extensions/Scribunto@wmf/1.39.0-wmf.25] Bump scribunto-stats cache version

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

ReleaseTaggerBot edited projects, added MW-1.39-notes (1.39.0-wmf.25; 2022-08-15); removed MW-1.39-notes (1.39.0-wmf.26; 2022-08-22).Aug 16 2022, 9:00 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL