Started abruptly at 2018-02-20T15:09:19 - https://logstash.wikimedia.org/goto/120f931c22267c8c77415143ec565877

parsing team, can you take a look here and give us some guidance on debugging this?

First impression: somebody is adding very large strip markers, which are tripping the memory limits when unstripped to add to the output.

Could be related to 939faea318d9c2107fab3a584bc1c023f3c592e9 which changed the regexp for strip markers. That should have made the match more restrictive, though. But that's precisely the regexp involved in this callback, so it's a pretty strong coincidence.

cc'ing brian wolff, since he wrote 939faea318d9c2107fab3a584bc1c023f3c592e9

I think tying this to the initiating web request would be helpful. As it stands, the logs do not tell us what is causing this. Is it possible to find out a more detailed error log that identifies the web request url?

A stack trace would also be helpful. Or at least the value of $type or $text in the unstripType caller.

Also possible that someone is actually trying to do the sort of XSS attack that bawolff was protecting against? Deliberately creating a very long strip marker?

EDIT (from bawolff): ...or a DOS attempt.

Its also possible that the real issue is somewhere else (during parsing), and stripstate handling is the straw that pushes the memory camel over the edge

It's not a DOS, there's not enough requests. It's just a broken bot hitting the same old revision via action=parse again and again. Specifically 256170852, a revision of [[Barack Obama]] from 2008. The solution is to find the person running this bot and to tell them to stop doing it.

In T187833#3987636, @tstarling wrote:

It's not a DOS, there's not enough requests. It's just a broken bot hitting the same old revision via action=parse again and again. Specifically 256170852, a revision of [[Barack Obama]] from 2008. The solution is to find the person running this bot and to tell them to stop doing it.

Looking at the diff of that revision, {{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|.}}}}}}}}}}}}}}}}}}}}} is the only thing out of the ordinary, so probably the trigger.

In T187833#3987610, @ssastry wrote:

I think tying this to the initiating web request would be helpful. As it stands, the logs do not tell us what is causing this. Is it possible to find out a more detailed error log that identifies the web request url?

Turns out I wasn't look in the right place. fatal.log on mwlog1001 has the traces and Krinkle provided https://logstash.wikimedia.org/goto/9f522ce47239a4373bc059024f286f5e for identifying the request url.

I revision-deleted the revision in question.

In T188227#4003661, @demon wrote:

Same issue was filed in T187833. I have a stack trace this time :)

{
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/parser/StripState.php",
  "line": 137
},
{
  "args": [
    "array"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/parser/StripState.php",
  "line": 127,
  "function": "unstripCallback",
  "type": "->",
  "class": "StripState",
  "object": "[object] (StripState: {})"
},
{
  "args": [
    "string",
    "string"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/parser/StripState.php",
  "line": 101,
  "function": "unstripType",
  "type": "->",
  "class": "StripState",
  "object": "[object] (StripState: {})"
},
{
  "args": [
    "string"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/parser/Parser.php",
  "line": 1373,
  "function": "unstripNoWiki",
  "type": "->",
  "class": "StripState",
  "object": "[object] (StripState: {})"
},
{
  "args": [
    "string",
    "boolean",
    "boolean"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/parser/Parser.php",
  "line": 446,
  "function": "internalParseHalfParsed",
  "type": "->",
  "class": "Parser",
  "object": "[object] (Parser: )"
},
{
  "args": [
    "string",
    "Title",
    "ParserOptions",
    "boolean",
    "boolean",
    "integer"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/StubObject.php",
  "line": 112,
  "function": "parse",
  "type": "->",
  "class": "Parser",
  "object": "[object] (Parser: )"
},
{
  "args": [
    "string",
    "array"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/StubObject.php",
  "line": 138,
  "function": "_call",
  "type": "->",
  "class": "StubObject",
  "object": "[object] (StubObject: {})"
},
{
  "args": [
    "string",
    "array"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/content/WikitextContent.php",
  "line": 329,
  "function": "__call",
  "type": "->",
  "class": "StubObject",
  "object": "[object] (StubObject: {})"
},
{
  "args": [
    "Title",
    "integer",
    "ParserOptions",
    "boolean",
    "ParserOutput"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/content/AbstractContent.php",
  "line": 516,
  "function": "fillParserOutput",
  "type": "->",
  "class": "WikitextContent",
  "object": "[object] (WikitextContent: {})"
},
{
  "args": [
    "Title",
    "integer",
    "ParserOptions"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/poolcounter/PoolWorkArticleView.php",
  "line": 145,
  "function": "getParserOutput",
  "type": "->",
  "class": "AbstractContent",
  "object": "[object] (WikitextContent: {})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/poolcounter/PoolCounterWork.php",
  "line": 123,
  "function": "doWork",
  "type": "->",
  "class": "PoolWorkArticleView",
  "object": "[object] (PoolWorkArticleView: {\"poolCounter\":{}})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/page/WikiPage.php",
  "line": 1133,
  "function": "execute",
  "type": "->",
  "class": "PoolCounterWork",
  "object": "[object] (PoolWorkArticleView: {\"poolCounter\":{}})"
},
{
  "args": [
    "ParserOptions",
    "integer",
    "boolean"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/api/ApiParse.php",
  "line": 602,
  "function": "getParserOutput",
  "type": "->",
  "class": "WikiPage",
  "object": "[object] (WikiPage: {\"mTitle\":{\"mTextform\":\"Rosetta@home\",\"mUrlform\":\"Rosetta@home\",\"mDbkeyform\":\"Rosetta@home\",\"mNamespace\":0,\"mInterwiki\":\"\",\"mFragment\":\"\",\"mArticleID\":3255539,\"mRestrictions\":{\"edit\":[],\"move\":[]},\"mCascadeRestriction\":false,\"mCascadingRestrictions\":null,\"mCascadeSources\":null,\"mRestrictionsLoaded\":true,\"mTitleProtection\":null,\"mDefaultNamespace\":0,\"mRedirect\":false},\"mDataLoaded\":true,\"mIsRedirect\":0,\"mLatest\":821745844,\"mPreparedEdit\":false})"
},
{
  "args": [
    "WikiPage",
    "ParserOptions",
    "boolean",
    "NULL",
    "Revision",
    "boolean"
  ],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/api/ApiParse.php",
  "line": 120,
  "function": "getParsedContent",
  "type": "->",
  "class": "ApiParse",
  "object": "[object] (ApiParse: {})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/api/ApiMain.php",
  "line": 1580,
  "function": "execute",
  "type": "->",
  "class": "ApiParse",
  "object": "[object] (ApiParse: {})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/api/ApiMain.php",
  "line": 542,
  "function": "executeAction",
  "type": "->",
  "class": "ApiMain",
  "object": "[object] (ApiMain: {\"mCommit\":false})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/includes/api/ApiMain.php",
  "line": 513,
  "function": "executeActionWithErrorHandling",
  "type": "->",
  "class": "ApiMain",
  "object": "[object] (ApiMain: {\"mCommit\":false})"
},
{
  "args": [],
  "file": "/srv/mediawiki/php-1.31.0-wmf.22/api.php",
  "line": 94,
  "function": "execute",
  "type": "->",
  "class": "ApiMain",
  "object": "[object] (ApiMain: {\"mCommit\":false})"
},
{
  "args": [
    "string"
  ],
  "file": "/srv/mediawiki/w/api.php",
  "line": 3,
  "function": "include"
}

Huh ..https://en.wikipedia.org/w/api.php?oldid=821745844 as well as https://en.wikipedia.org//w/api.php?action=parse&prop=iwlinks|externallinks&format=json&oldid=821745844 render just fine.

https://logstash.wikimedia.org/goto/8c64c21a6fa00945d06a0f07e3ad138f is the logstack url for the full traces in case others see something that I am missing there.

If it is a bot that is requesting external links on a page, could that be a bot that updates links on a page to IA links for dead links? While there is probably an issue here in the parser (to be determined), the bot seems to be repeatedly retrying the same failing request.

@ssastry: this one fails for me: https://en.wikipedia.org/w/api.php?action=parse&prop=iwlinks|externallinks&format=json&oldid=255139603

https://en.wikipedia.org//w/api.php?action=parse&oldid=255139603 fails as well.

In T187833#4003967, @mmodell wrote:

@ssastry: this one fails for me: https://en.wikipedia.org/w/api.php?action=parse&prop=iwlinks|externallinks&format=json&oldid=255139603

Looks like that is a very similar revision to the one that started this (which Tim had rev-del'ed).

Diff: https://en.wikipedia.org/?diff=255139603&diffonly=1

   Quick guide to Rosetta and its graphics

-  
+ {{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|{{unblock|.}}}}}}}}}}}}}}}}}}}}}
  
  Like all BOINC projects, Rosetta@home runs in the background of the user's computer using idle computer power,

The same vandal made a few more similar edits in 2008, per https://en.wikipedia.org/wiki/Special:Contributions/Endingkey.

Yeah, deleting the revision obviously isn't the ultimate solution to this issue ;)

Replying to some IRC discussion

<subbu> TimStarling, doing it once, twice, thrice .. and looking at the expandtemplates output shows that the size of the output starts blowing up rapidly.
<subbu> roughly 4^(nesting level-1) * 4k

I see that in my own testing, but the StripState size (var_dumped) isn't increasing quite as fast.

<TimStarling> the post-expand include size is meant to limit massive preprocessor expansions, but I guess strip marker expansion is not included

Yeah, it seems to be counting the length of the strip marker rather than the length of the text inside the marker.

<Krinkle> TimStarling: Hm.. do we use strip markers for template parameters like {{{1}}} etc.? I thought maybe the expansion is big because of the recursion there.
<Krinkle> BUt afaik we don't use stripmarkers for those

We don't. But this template does {{#tag:nowiki|{{{1}}}}} three times, and each one of those creates a strip marker. What it probably really wants is a way to get the unparsed wikitext of {{{1}}} to pass to #tag:nowiki, but that's not available so it does the next best thing (and which will generally work for normal uses of the template).

• {{unblock|.}} produces something like 3707 bytes of text. This includes three strip markers hiding 1 byte each (and two more for 29 bytes).
• {{unblock|{{unblock|.}}}}, produces something like 7412 bytes of text, which looks like wrapping the output of the template around itself once. But it also includes three strip markers hiding 3707 bytes each that show up when thing get unstripped.
• {{unblock|{{unblock|{{unblock|.}}}}}}, produces something like 11117 bytes of text. Again, it looks like it adds one more level of wrapping. But it also includes three strip markers hiding 3707 bytes each and three more hiding 7412 bytes each, and each of those 7412-byte markers has another copy of the three 3707-byte markers for a total of 66720 extra bytes that show up when thing get unstripped.
• {{unblock|{{unblock|{{unblock|{{unblock|.}}}}}}}} continues the trend. It produces only 14822 bytes of text directly, but it has all the strip markers from the previous version plus three strip markers hiding 11117 bytes each that each have a copy of the three 3707-byte markers and the three 7412-byte markers (that each in turn have the three 3707-byte markers), for a total of 300231 extra bytes that show up when thing get unstripped.

In each case it's only the directly produced bytes that get counted against the post-expand and argument size limits, while the real size explosion is in the three strip markers that each have three strip markers inside, recursively.

Very nice analysis @Anomie!

Fix uploaded at https://gerrit.wikimedia.org/r/#/c/415207/ . Any objections to removing the policy? This is not a DOS attack. It's apparently not even a DOS attack vector, since the memory limit is doing its job, and the CPU time is short.

In T187833#4008980, @tstarling wrote:

Any objections to removing the policy?

Done.

Change 415207 merged by jenkins-bot:
[mediawiki/core@master] Limit total expansion size in StripState and improve limit handling

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