Etherpad-lite: Applied attributes can cause apply mismatched. Needs load test coverage to replicate.

[JohnMcLear]

This initial comment seems irrelevant.

This is a bit of an edge case but it can happen. It only happens on very active pads (think 10s of edits a second).

To replicate.

1. Enable loadTesting.
2. Run loadTesting
3. Copy / paste the padId into the browser.

What happens

Pad wont load

What should hapen

Pad should load.

More debug info

Pad will successfully load and can be edited once Load Testing is complete
If you are already on the pad no errors come and it works great.

Error is

Error: Failed assertion: mismatched apply: 10984 / 11740

Assumption

My assumption is that between the time of us delivering the pad object including the baseRev # there has been an additional change meaning that the next change fails causing mismatched apply.

Consider this scenario..

Rev # | 
1    | <-- we connect here
2    | <-- has been an edit here.
3    | <-- is the first commit we receive from the server

The logic is this:

exports.applyToText = function (cs, str) {
  var unpacked = exports.unpack(cs);
  exports.assert(str.length == unpacked.oldLen, "mismatched apply: ", str.length, " / ", unpacked.oldLen);

I think the solution is Etherpad can "request" previous revision upon receiving a revision that's "in the future" and apply that before the latest revision. Essentially upon receiving 3 and knowing it's at 1 it also requests [2] and applies [2] before 3 ?

I tried to create this same problem on the etherpad-cli-client with etherpad-load-test and can't. The messages always appear to load in order. Next step is to simulate a delay between CLIENT_VARS and NEW_CHANGES and see what happens.

[JohnMcLear]

Interestingly using the CLI client this never happens. So this has to be a web client issue.

Line 283 of collab_client.js

    if (msg.type == "NEW_CHANGES")

This is where the error appears to be coming from..

It appears the revision counts aren't being well handled..

[sus16cn]

Hi John, that's right!
I ran the loadTest on the Test server: node app.js http://127.0.0.1:9001/p/load -d 180 -l 100 -a 500
and also on the Productive: node app.js http://127.0.0.1:9001/p/load -l 50 -a 12
there were no Problems.

A user confirmed to me, if you are already in the pad, you have no problems. The problem occurs with us from 10 to 15 users.

[JohnMcLear]

180 / 500 are unrealistic numbers imho! 500 authors each doing 1 edit per second is going to break the Internet 🖌️

[yorickreum]

Hi @JohnMcLear, sure. But I can affirm, the Etherpad installations withstood it! Impressing. However, this also means that whatever exactly crashes our instance (see closed issue https://github.com/ether/etherpad-lite/issues/4090) probably is not really depending on the activity in the pad, which probably means that it is yet another issue.

[JohnMcLear]

Noted @yorickreum. But if I can fix this issue it's probable/possible it will fix your issue. The mismatched apply is essentially a race condition that I need to remedy and this issues bug fix will hopefully cover all eventualities of that race condition happening irrespective of the cause.

[JohnMcLear]

Interesting. mismatched apply only is applicable to applying changeset to a string, not an "append" of pad content which is the only thing the loadTest tool is doing.

I need to make the loadTest tool also simulate applying a changeset to a string.

[JohnMcLear]

Just an update on this in case things go stale.

I can't remember the logic for applying an attribute to a selection using just the changeset.js without the document attribute manager so I have asked for help.

It's something someone more recently familar will be able to help with. Once I have that logic I will include it in the load tests and hopefully be able to simulate the bug.

If there are no further updates from me on this it's because I ran out of time.

[Oremountainflorian]

Just a short update/report:

Yesterday the problem occured again for me in a pad with only 2 users so I doesn't seem to be dependent on the number of users as @yorickreum already wrote (see https://github.com/ether/etherpad-lite/issues/4090). The problem arose after 2 minutes and lasted for 1 minute before I closed the tab and reopened the pad in a new tab which eventually solved the problem for the next hour. I use Firefox 78.0.2.

[JohnMcLear]

@Oremountainflorian I'd be tempted to suggest testing without plugins to see if it continues.

Within the 1 minute of the error persisting did you attempt to refresh your browser? Changesets are not stored persistently so it makes no sense that a refresh of low activity did not fix. I feel some plugin fuckery could be afoot