Page MenuHomePhabricator
Create Task
Maniphest T264257

Fix ParserOutput corruption wmf.10 -> wmf.11
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

We're seeing a 100-1000 times increase of errors per minute across wikis and servers due to what appears to be invalid CacheTime objects stored in ParserCache by wmf.11 code,. We have rolled back to wmf.10, and the above patch has invalidated the affected cache entries.

Link to example errors in Kibana:
https://logstash.wikimedia.org/goto/e4ff1589fd26334c21e663a6be6ba1be

Each page view seems to experience a cascading chain of about ~10 different PHP errors/warnings:

PHP Warning: array_intersect(): Argument #1 is not an array
#1 /srv/mediawiki/php-1.36.0-wmf.10/includes/parser/ParserOptions.php(1397): array_intersect(NULL, array, array)
#2 /srv/mediawiki/php-1.36.0-wmf.10/includes/parser/ParserCache.php(251): ParserOptions->optionsHash(NULL, Title)
#3 /srv/mediawiki/php-1.36.0-wmf.10/includes/parser/ParserCache.php(283): ParserCache->getKey(WikiPage, ParserOptions, integer)
#4 /srv/mediawiki/php-1.36.0-wmf.10/includes/page/Article.php(733): ParserCache->get(WikiPage, ParserOptions)

This appears to be the first one in the chain, it seems CacheTime->mUsedOptions might be null or unset?

Lots of cascading due to the required $forOptions array parameter being null, which are causing wrong cache keys to be used for reading or writing the cache:

PHP Warning: in_array() expects parameter 2 to be array, null given
/srv/mediawiki/php-1.36.0-wmf.10/extensions/Math/src/MathHooks.php:116      
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.36.0-wmf.10/extensions/Math/src/MathHooks.php(116): in_array(string, NULL)
#2 /srv/mediawiki/php-1.36.0-wmf.10/includes/HookContainer/HookContainer.php(331): MathHooks::onPageRenderingHash(string, User, NULL)
#3 /srv/mediawiki/php-1.36.0-wmf.10/includes/HookContainer/HookContainer.php(138):

Details

SubjectRepoBranchLines /-
HACK/ParserCache: Force cache-miss if mUsedOptions is undefinedmediawiki/coremaster 10 -0
HACK/ParserCache: Force cache-miss if mUsedOptions is undefinedmediawiki/corewmf/1.36.0-wmf.11 10 -0
Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""mediawiki/corewmf/1.36.0-wmf.11 60 -146
Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""mediawiki/coremaster 61 -146
HACK/ParserCache: Force cache-miss if mUsedOptions is undefinedmediawiki/corewmf/1.36.0-wmf.10 10 -0
Reject ParserCache entries from the last wmf.11 deploymentoperations/mediawiki-configmaster 8 -4
Customize query in gerrit

Related Objects
Search...

Event Timeline

Krinkle created this task.Sep 30 2020, 11:58 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 30 2020, 11:58 PM
gerritbot added a comment.Sep 30 2020, 11:58 PM

Change 631318 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] Reject ParserCache entries from the last wmf.11 deployment

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

gerritbot added a project: Patch-For-Review.Sep 30 2020, 11:58 PM
Krinkle added a parent task: T263851: Disallow dynamic property access on ParserOutput.Oct 1 2020, 12:00 AM
gerritbot added a comment.Oct 1 2020, 12:01 AM

Change 631318 merged by jenkins-bot:
[operations/mediawiki-config@master] Reject ParserCache entries from the last wmf.11 deployment

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

Krinkle added a project: Wikimedia-Incident.Oct 1 2020, 12:01 AM
Krinkle mentioned this in T263851: Disallow dynamic property access on ParserOutput.
Maintenance_bot removed a project: Patch-For-Review.Oct 1 2020, 12:10 AM
• Pchelolo subscribed.Oct 1 2020, 12:21 AM

My fault. https://gerrit.wikimedia.org/r/c/mediawiki/core/ /629405 has to be reverted, which would make it a 'revert revert revert'

gerritbot added a comment.Oct 1 2020, 12:26 AM

Change 631239 had a related patch set uploaded (by Ppchelko; owner: Ppchelko):
[mediawiki/core@master] Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""

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

gerritbot added a project: Patch-For-Review.Oct 1 2020, 12:26 AM
gerritbot added a comment.Oct 1 2020, 12:43 AM

Change 631324 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.36.0-wmf.10] HACK/ParserCache: Forche cache-miss if mUsedOptions is undefined

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

DannyS712 subscribed.Oct 1 2020, 12:51 AM
gerritbot added a comment.Oct 1 2020, 12:52 AM

Change 631324 merged by Krinkle:
[mediawiki/core@wmf/1.36.0-wmf.10] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

ReleaseTaggerBot added a project: MW-1.36-notes (1.36.0-wmf.10; 2020-09-22).Oct 1 2020, 1:00 AM
Krinkle added a comment.Oct 1 2020, 1:33 AM

https://grafana.wikimedia.org/d/000000106/parser-cache

Screenshot 2020-10-01 at 02.31.08.png (1×2 px, 207 KB)

Rejections are working as expected. Will recover soon enough.

https://logstash.wikimedia.org/app/kibana#/dashboard/mediawiki-errors

Errors have stopped as of 01:27 UTC when the last sync finished.

See chat log at:
https://wm-bot.wmflabs.org/logs/#wikimedia-sre/20200930.txt
https://wm-bot.wmflabs.org/logs/#wikimedia-sre/20201001.txt

Good night.

Krinkle assigned this task to • Pchelolo.Oct 1 2020, 1:35 AM
• Pchelolo merged a task: T264198: PHP warnings from ParserOptions::optionsHash.Oct 1 2020, 1:59 AM
• Pchelolo added subscribers: Nikerabbit, Ammarpad.
gerritbot added a comment.Oct 1 2020, 2:02 AM

Change 631240 had a related patch set uploaded (by Ppchelko; owner: Ppchelko):
[mediawiki/core@wmf/1.36.0-wmf.11] Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""

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

• Pchelolo added a comment.Oct 1 2020, 2:08 AM

This is all clearly may fault. My apologies, and thank you to @Krinkle and everyone involved for dealing with the mess I've caused.

https://gerrit.wikimedia.org/r/c/mediawiki/core/ /631239 reverts the faulty patch in master,
https://gerrit.wikimedia.org/r/c/mediawiki/core/ /631240 is a backport to wmf.11

• mmodell added subscribers: hashar, • mmodell.Oct 1 2020, 4:06 AM

wmf.11 is completely rolled back, hopefully it can roll out tomorrow but I'm not too confident. If @hashar wants to try it during EU window that's up to him ;)

Nikerabbit added a comment.Oct 1 2020, 6:46 AM

This is not the first time a bug I've noticed (and reported) in translatewiki.net also causes issues in WMF production. Some of them I mark as train blockers when it is obvious they will affect WMF production too, but some issues like this are not so obvious. Any ideas how to improve this process so that this won't happen again?

hashar added a comment.Oct 1 2020, 1:35 PM
In T264257#6507430, @mmodell wrote:

wmf.11 is completely rolled back, hopefully it can roll out tomorrow but I'm not too confident. If @hashar wants to try it during EU window that's up to him ;)

I don't feel very confident to roll it without assistance from people knowing about the issue / ParserCache being available. I will look at being available in my evening to assist though.

Is the issue due to unserializing a ParserOutput object that got serialized based on a different version of the class? If so that has hit us several time in the past. At least T229366 and we had some test to check the unserialization: https://gerrit.wikimedia.org/r/c/mediawiki/core/ /526575/2/tests/phpunit/includes/parser/ParserOutputTest.php

If that is the same problem, maybe we would need a specific test that runs whenever ParserOutput is changed and ensure that we can unserialize from a previous version. Or at least that the cache key is altered.

• Pchelolo added a comment.Oct 1 2020, 1:46 PM

So, as I understand it, the issue is that my patch has moved a property up the class hierarchy, and I've added fallbacks for reading old ParserOutput with new version of the code, tested that path, added a unit test, all that. However, I have completely forgot about rolling back, and making sure the old version of the class can read the new serialized data. Rookie mistake.

As for making sure this doesn't happen again: T263579 should help - as a part of Parsoid integration we are going to change the serialization format to JSON. We should make sure to include more explicit upgrade/downgrade logic in JSON serialization since we will have much more control over it.

As for moving the train forward, complete revert of the faulty patch (631240) should be enough (but not of Timo's hacks yet. Those will need to be reverted later when we're sure there's no bad ParserOutput in the cache, I'll do that). However at this point I do not have enough self-confidence to make any definitive statements.

• mmodell added a comment.Oct 1 2020, 3:17 PM

I too am pretty uncertain about wmf.11, there were actually multiple issues that cropped up yesterday and it was hard to tell which ones were real because we had a lot of nonsensical / seemingly impossible errors that were caused by opcode cache corruption. The corruption errors were obscuring the other issues for a while.

Krinkle added a comment.Oct 1 2020, 6:01 PM

@Pchelolo Can you put the various patches that need to be rolled out to unblock this on the deploy calendar and/or coordinate with releng?

Krinkle triaged this task as Unbreak Now! priority.Oct 1 2020, 6:02 PM

(Train blocker)

• Pchelolo added a comment.Oct 1 2020, 6:05 PM

It has been reverted in master, wmf.11 backport needed to unblock is https://gerrit.wikimedia.org/r/c/mediawiki/core/ /631240

• Pchelolo mentioned this in T264348: Run RejectParserOutput hook much earlier, possibly multiple times.Oct 1 2020, 6:23 PM
gerritbot added a comment.Oct 1 2020, 6:24 PM

Change 631239 merged by jenkins-bot:
[mediawiki/core@master] Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""

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

gerritbot added a comment.Oct 1 2020, 6:25 PM

Change 631471 had a related patch set uploaded (by Ppchelko; owner: Krinkle):
[mediawiki/core@master] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

gerritbot added a comment.Oct 1 2020, 6:28 PM

Change 631473 had a related patch set uploaded (by Ppchelko; owner: Krinkle):
[mediawiki/core@wmf/1.36.0-wmf.11] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.12; 2020-10-05; NEVER DEPLOYED); removed MW-1.36-notes (1.36.0-wmf.10; 2020-09-22).Oct 1 2020, 7:00 PM
gerritbot added a comment.Oct 1 2020, 7:11 PM

Change 631473 abandoned by Ppchelko:
[mediawiki/core@wmf/1.36.0-wmf.11] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

Reason:
created another one.

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

gerritbot added a comment.Oct 1 2020, 7:12 PM

Change 631473 restored by Ppchelko:
[mediawiki/core@wmf/1.36.0-wmf.11] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

• Pchelolo added a comment.Oct 1 2020, 7:19 PM

For the ParserCache blocker, this is the chain of back ports that moves wmf.11 to the same exact state as wmf.10 and master for the parserCache: They are to be merged before deployment.

https://gerrit.wikimedia.org/r/c/mediawiki/core/ /631240/2 https://gerrit.wikimedia.org/r/c/mediawiki/core/ /631473/2

• mmodell added a comment.Oct 1 2020, 7:29 PM

@Pchelolo: Should we close this or leave it open? (not sure if there is remaining work besides merging the aforementioned patches?)

• Pchelolo closed this task as Resolved.Oct 1 2020, 7:31 PM

This should be resolved now yes. I'm going to create a couple followup tasks and will cross reference them to here.

gerritbot added a comment.Oct 1 2020, 7:50 PM

Change 631240 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.11] Revert "Revert "Revert "Hard deprecate all public properties in CacheTime and ParserOutput"""

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

gerritbot added a comment.Oct 1 2020, 7:50 PM

Change 631473 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.11] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.11; 2020-09-29); removed MW-1.36-notes (1.36.0-wmf.12; 2020-10-05; NEVER DEPLOYED).Oct 1 2020, 8:00 PM
Stashbot mentioned this in T263177: 1.36.0-wmf.11 deployment blockers.Oct 1 2020, 8:08 PM

Mentioned in SAL (#wikimedia-operations) [2020-10-01T20:08:13Z] <twentyafterfour@deploy1001> Synchronized php-1.36.0-wmf.11/includes/parser/: sync ParserCache patches to unblock the train T264257 T263177 (duration: 00m 59s)

gerritbot added a comment.Oct 5 2020, 1:58 PM

Change 631471 merged by jenkins-bot:
[mediawiki/core@master] HACK/ParserCache: Force cache-miss if mUsedOptions is undefined

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

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.12; 2020-10-05; NEVER DEPLOYED); removed MW-1.36-notes (1.36.0-wmf.11; 2020-09-29).Oct 5 2020, 2: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 · Credits