@mobrovac @GWicke this looks like a case where data-parsoid fwded to Parsoid is for the wrong render?

@ssastry: Agreed, the symptoms are consistent with some data-parsoid or element ID issue. One interesting aspect is that only some links are affected, but not all. This could indeed point towards a mis-match between data-parsoid & HTML ids.

There are no errors matching this title or related revisions in logstash, which suggests that Cassandra and RESTBase didn't encounter any abnormal situations while processing this request. I'm afraid that this will be hard to figure out unless we either find more information, or find a way to reproduce this.

Possibly related wikitext replaced with HTML: https://en.wikipedia.org/w/index.php?title=Environmental_issues_in_Puget_Sound&diff=718886332&oldid=718881357 , https://en.wikipedia.org/w/index.php?title=Streamflow&diff=719000766&oldid=719000660 , https://en.wikipedia.org/w/index.php?title=Illuminati_in_popular_culture&diff=718980022&oldid=718979969

I don't think that this is a RESTBase issue. First of all, we didn't touch/deploy anything related to VE or Parsoid recently. Secondly, the html and data-parsoid stored in RB for the affected revision of the Jungle_cat article seem to match:

• html: https://en.wikipedia.org/api/rest_v1/page/html/Jungle_cat/718896396/f782e762-1365-11e6-aa3f-260bd5c691de
• data-parsoid: https://en.wikipedia.org/api/rest_v1/page/data-parsoid/Jungle_cat/718896396/f782e762-1365-11e6-aa3f-260bd5c691de

If you look at the history for these edits, including the ones referenced on the VE/Feedback page, it always seems to happen when a user makes a few subsequent edits in a flurry.

CheckWiki scans for HTML syntax for lists and section headers. A scan is made everyday at 0z. The amount of <li> and <h*> in articles dramatically increased on the May 5 0z scan. Scans since then have shown dramatically higher numbers. Something changed on May 4 as these errors were not present before then.

For awhile, VE has a problem of adding <h*> into articles, but these occurred when new section headers were added. In the above problem, section was previously present and nothing around it changed.

For the category barf VE is producing, there was a similar bug, T72894, over a year ago.

Parsoid had a deployment on the 4th but it only updated a cached file. There was a more significant change on the 2nd, but that doesn't seem to fit the timeline.

However, there was an outage on the 4th, in T134537, and maybe this is somehow a consequence of what happened there.

@Bgwhite is the data you're referencing publicly available?

Looking at the deployment calendar & the server admin log, Wed 4th saw the following deployments:

• the MediaWiki train group1 to 1.27.0-wmf.23
• Parsoid b0d015fa
• VisualEditor fixes for wmf.23: https://gerrit.wikimedia.org/r/#/c/287017/

Then, there was a RB outage / slowness starting Wed 5th, around 02:30-03:30UTC: T134537

Later on Thursday the 5th (09:22 UTC), there was also a RESTBase deploy:

• RESTBase 653e

The Parsoid change looks minor, but there were some data-parsoid related changes two days earlier. However, if this issue started only on the 4th as indicated by @Bgwhite, then those should not be relevant.

@Jdforrester-WMF @Krenair @Esanders, were there any VE changes deployed that could be potentially related to this? Anything related to how ETags are updated in VE or forwarded to the API, especially on repeat edits?

@Arlolra

is the data you're referencing publicly available?

Webpage is at: https://tools.wmflabs.org/checkwiki/cgi-bin/checkwiki.cgi?project=enwiki&view=project
Error #49 is section headers. #12 is lists. For an individual error, click on "description" to get a current and "done" article listings.

#49 rarely goes over 2 new errors a day.
#12 rarely goes over 2 new errors a week.

@Bgwhite thanks.

What I said in T134593#2277888 still seems to hold, though it isn't on every subsequent edit and doesn't need to happen all that quickly (couple minutes).

Here's a good example,
https://fr.wikipedia.org/w/index.php?title=Stade_Oc%C3%A9ane&action=history

So, there must be some editing pattern causing dp to be misattributed.

In T134593#2278285, @GWicke wrote:

were there any VE changes deployed that could be potentially related to this? Anything related to how ETags are updated in VE or forwarded to the API, especially on repeat edits?

I did a quick look and didn't find anything related. Certainly don't remember any changes around that area.
(also, use this account for VE things please)

VE sending an outdated ETag / If-Match header could cause symptoms like this. RESTBase logs indicate that it did not fall back to the inline mw:TimeUuid tag, which very likely means that an ETag header was passed at all times. However, it's still possible that this ETag was outdated in some cases.

@Pchelolo & I tried to provoke something like that manually by quickly editing the same page in sequence, but didn't have much luck.

We are now looking into adding a sanity check comparing the mw:TimeUuid with the passed-in ETag to establish whether there are edits where those two do not agree. This should establish whether this is a RB client issue or not.

A patch for the sanity check is now up at https://github.com/wikimedia/restbase/pull/608. If things go to plan, we'll deploy this tomorrow.

In T134593#2279039, @GWicke wrote:

A patch for the sanity check is now up at https://github.com/wikimedia/restbase/pull/608. If things go to plan, we'll deploy this tomorrow.

It has been deployed as part of today's deploy. We will monitor the situation in the upcoming period and report back should there be any findings.

Some more data:

• So far, no mis-matches between If-Match header and mw:TimeUuid were logged.
• VE is still sending about 60 html2wt requests per 24 hours that are missing an If-Match header: https://logstash.wikimedia.org/#dashboard/temp/AVSbqItO0z-7ykXOH3V3

@Bgwhite, have you seen new instances of this issue in the last 24 hours?

@Bgwhite, have you seen new instances of this issue in the last 24 hours?

I'll check after the Checkwiki 0z run get finished.

I did not see any new instances.

@GWicke did you deploy anything that would explain why it is so?

@Bgwhite, thanks!

@Arlolra, we deployed a new version half way through the last 24 hours, but it did not contain any changes that are likely to affect the behavior in this issue.

For completeness, we did another deploy this morning which improves TID checks and logs if a (literal) null value is received for it, so hopefully this will make it easier to get to the bottom of this.

Nothing visible in the logs at this point, though.

So this is "fixed" (worked around) in production, but we don't yet know the cause?

There are no fixes or work-arounds in RB. The only related changes we deployed added some debug prints to narrow down possible causes, which haven't emitted anything so far. This means that the things those debug prints tested for were not the culprit.

In T134593#2286871, @GWicke wrote:

There are no fixes or work-arounds in RB. The only related changes we deployed added some debug prints to narrow down possible causes, which haven't emitted anything so far. This means that the things those debug prints tested for were not the culprit.

https://github.com/wikimedia/restbase/pull/608/files looks like it didn't set the contents of tid in that error state, though?

https://github.com/wikimedia/restbase/pull/608/files looks like it didn't set the contents of tid in that error state, though?

If you mean the new check / log case in https://github.com/wikimedia/restbase/pull/608/files#diff-d91965930eda1e26c9b5db0d3041c4acR597, then that only triggers if the tid is already truthy. Previously, we didn't even look at the mw:TimeUuid value in that case, as the supplied tid takes precedence. There is no change in behavior.

See also T135171 for the related investigation into missing if-match headers in some VE requests.

New reports @ https://en.wikipedia.org/wiki/Wikipedia:VisualEditor/Feedback#Messing_up_categories

Here is a summary of the status quo:

1. The way the RESTBase code is structured guarantees that a) data-parsoid is only loaded when the original HTML was already found (matching the exact revision and tid), and b) data-parsoid is loaded using the exact same revision / tid specified by VisualEditor in its save request.
2. The change pattern indicates that a large part of the page was not serialized with selser. This suggests that the original HTML differed, triggering non-selser serialization. This would primarily be the case if VisualEditor passed an incorrect title / base revision / tid tuple to RESTBase. To me, this seems to be the most likely candidate hypothesis.

We already have instrumentation in RESTBase comparing the header-supplied revision/tid with that in the HTML head <meta> element. This check did not trigger for any problematic edit so far, suggesting that VisualEditor sends a consistent header & HTML head section.

@AlexMonk-WMF, is there any chance that VE itself, or the speculative save feature, would combine an etag & HTML head from an older revision with HTML from a newer revision? Are there ways to instrument VE to rule out revision mis-matches? Are there specific usage patterns like repeat edits that trigger this?

One thing I did recently notice is that sometimes quick repeat edits (save, then hit the edit tab again) in VE end up loading an old revision. The last time I experienced this, a banner saying "you are editing an old revision" popped up at the top. Could there be a race condition behind this, possibly related to MySQL replication lag? Could this lead to a state in VE where its idea of etag & HTML head diverges from the body content?

In T134593#2476426, @GWicke wrote:

@AlexMonk-WMF, is there any chance that VE itself, or the speculative save feature, would combine an etag & HTML head from an older revision with HTML from a newer revision? Are there ways to instrument VE to rule out revision mis-matches? Are there specific usage patterns like repeat edits that trigger this?

I think instrumenting this would be a good idea, but it would probably have to be on the RESTbase/Parsoid end. They (or one of them) behave differently when the E-Tag/head mismatches with the content, so it should be easier to detect it there (or somewhere on the server side) than on the client side.

In T134593#2488789, @GWicke wrote:

One thing I did recently notice is that sometimes quick repeat edits (save, then hit the edit tab again) in VE end up loading an old revision. The last time I experienced this, a banner saying "you are editing an old revision" popped up at the top. Could there be a race condition behind this, possibly related to MySQL replication lag? Could this lead to a state in VE where its idea of etag & HTML head diverges from the body content?

If you saw that, then the MediaWiki API response knew that the revision was old. I have found buggy behavior that would make VE do an oldid edit the second time, but I couldn't get that to result in an E-Tag mismatch: we have logic ensuring the revid in the about attribute of the <html> tag in the RB response matches what we expect. From reading the code I don't see how either the E-Tag or the <head> of the wrong revision could end up being used for saving, even when editing multiple times, and I can't reproduce that behavior either.

In T134593#2494565, @Catrope wrote:

I have found buggy behavior that would make VE do an oldid edit the second time

I reported this as T141330: ?oldid=mostRecentRevId causes strange behavior on second edit and went down a small rabbit hole of things that scared me (stale state etc). I didn't find anything that could explain E-Tag or <head> mismatches, but I found enough other concerning cases of stale data being used and generally weird things happening in the oldid-equals-current edge case that it may be worth trying my patch for that bug and seeing if that fixes (or works around / stops exposing) this issue.

@Catrope, in my case I was editing the latest version of the article (without oldid parameter), but got an "you are editing an old version" warning after re-opening VE right after a save. I'm not sure if the URL had changed to include an oldid at that point.

I guess the most obvious next thing to do is to wait & see if the issue is fixed. I don't have other ideas for instrumentation in RB, as we are already checking for consistency between If-Match & HTML head information. We don't have an easy way to figure out if the edited body is matching the supplied revision / uuid. Parsoid is checking just that (with DOM diffing), and seems to think that it does not match when this error occurs, as evidenced by it not using selser for large parts of the page.

Culling out couple more recent links from the VE/Feedback archives so it is easier to reference them without having to go digging through archives:

• https://en.wikipedia.org/w/index.php?title=Lisa_Madigan&type=revision&diff=729947651&oldid=729947609
• https://en.wikipedia.org/w/index.php?title=Sturgis%2C_Michigan&type=revision&diff=729955040&oldid=729954866

Here is an older one:

• https://fr.wikipedia.org/w/index.php?title=Stade_Oc%C3%A9ane&type=revision&diff=125963955&oldid=125963854

So, Arlo's observations earlier are correct that this seems to happen *only* when one VE edit is followed by another VE edit. Looks like that is where the focus ought to be in VE & RESTBase.

Since <link> and <meta> tags (especially those for default sort, category links, language links, etc.) should never be generated as HTML tags, if during serialization we detect those tags getting a 'html' syntax flag, Parsoid could abort serialization and log an error. This can do two things: (a) avoid corruptions in some of these scenarios -- not all will be prevented (b) continue to log errors for debugging.

Since the VE changes, there have been no new reports on https://en.wikipedia.org/wiki/Wikipedia:VisualEditor/Feedback, which is encouraging. Lets keep this task open for a few more weeks.

Thank you everyone!