[Bug] Faild assertion: mismatched apply

[Oremountainflorian]

System

We have integrated the latest version of Etherpad (1.8.4) into our platform. Occurs independently from used browser.

The following plugins are also installed:

• ep_font_color "version": "0.0.11"
• ep_comments_page "version": "0.1.3"
• ep_embedded_hyperlinks_2 "version": "1.2.2"
• ep_heading2 "version": "0.1.3"
• ep_align "version": "0.2.0"
• ep_author_hover "version": "0.2.0"
• ep_table_of_contents "version": "0.2.0"
• ep_adminpads2 "version": "0.0.4"

Server Setup Information:

• Version of Etherpad: 1.8.4
• Operating System: Linux 5.5.0-2-amd64 Added Makefile #1 SMP Debian 5.5.17-1 (2020-04-15) x86_64 GNU/Linux
• Deployment Method: Manual install, git tag 1.8.4 (commit 89a155f) with systemd service
• Number of Running Instances: 1
• DB Replicaset Oplog: (default)
• NodeJS Version: v10.21.0
• NPM Version: 6.14.4
• MariaDB Version: 10.3.22-MariaDB-0+deb10u1 Debian 10
• operating behind nginx reverse proxy => setup: https://github.com/ether/etherpad-lite/wiki/How-to-put-Etherpad-Lite-behind-a-reverse-Proxy

Problem description

On our meetings (usually with 5-15 persons) I get kicked out of the pad and I can't reenter it for about 1-2 min. During this time, the following error messages appear:

Every second a new error pops up underneath the others, so there are 4 error messages where the pads content would normally be. The errorId changes, but the error message is always the same (faild assertion: mismatched apply). Furthermore, the second number after the error increases by 4 whereas the first number 7947 stays constant. Nothing special in line 24, sometimes the line number doesn't even exist, so it seems the error is at scriptElement line 13 > function at line 14. But which script and which function are we speaking of?!

After 1-2 min, everything works fine again. Unfortunately it's really hard to replicate, this happens to some of us but doesn't happen to others. Seems to be independently from the used browser. Also the moment in time the error occurs differs, sometimes after 5 minutes, sometimes after 15 minutes...

Any ideas? Best wishes, Flo

[JohnMcLear]

This sounds like #4040 ?

[JohnMcLear]

What version of ueberDB do you see?

cat src/package.json | grep ueber

[Oremountainflorian]

Indeed, issue #4040 seems to be related!

@JohnMcLear "ueberdb2": "0.4.9"

[JohnMcLear]

Ack,

musings

1. It's unlikely it's MariaDB / Database related as ueber @ 0.4.9 is stable.
2. It could be just the volume of traffic from your users but 5-10 people should be fine.
3. This is probably a legacy/old bug but we generically caught it before and now we're isolating the problem down to a specific thing.

todo

We provide a loadTest tool for you to simulate load, you could simulate and see why you are being disconnected.

If we can figure out the disconnect reasoning that's a good start because we think we already know why reconnect fails.

https://github.com/ether/etherpad-load-test is the tool and the usage guide, it's really easy to use and if you can run a few load tests and find a certain criteria that causes your problem that would be good. I could then use that same criteria and attempt to replicate locally.

Also run the tests with and then without plugins, just to see if it's plugin related (which I doubt it is).

#4040 is the root issue, but if we can keep this issue open to discover the reasoning behind disconnect then that will aid #4040s debug.

[Chostakovitch]

I see a lot of mismatched apply errors in my Etherpad instance log, for pads which are not on heavy load (5/10 users for a single pad, maximum). However we do not get reports about users being disconnected.

If it is useful, I can find some time to perform a loadTest as well.

[JohnMcLear]

@Chostakovitch are you seeing any errors if you don't run plugins? Yes, more testing is useful.

[yorickreum]

We also encounter this issue. Our pads are used by round about 15 users (+- 5 users). We see a lot of [2020-06-18 15:46:35.595] [WARN] client - Error: Failed assertion: mismatched apply: 9329 / 9346 like errors in the error log and our users can not load the pad anymore. The loading starts working again after some time (usually hours). Restarting etherpad does not appear to help.

[JohnMcLear]

@yorickreum with or without plugins?

[sus16cn]

hi, I answer for yorickreum, we have no plugins installed. The problem still occurs and the pad can no longer be loaded. The chat at the bottom right, but still works, a user told me today. We also have the version Etherpad (1.8.4)
Any idea what we can do?
Thank you, Susi

[JohnMcLear]

Is the pad URL public?

[sus16cn]

no, the pad is created via a Moodle instance. I suspect the error happens when multiple students access the same line.
Later (usually hours), the pad can be reloaded.

[JohnMcLear]

Later should be just a few seconds after the last edit... Are you sure it's a few hours? Can you replicate?

[sus16cn]

no, it takes much longer and is not in the range of seconds.
I don't think it will work until all the students have left the pad, but I'm not sure.
It only happens under load and so i can't replicate it, easily.
But I can see this in /var/log/etherpad/etherpad-lite.log , in settings.json i have:
"loglevel": "INFO",

585034 [2020-07-08 12:35:51.627] [INFO] ueberDB - Flushed 4 values
585035 [2020-07-08 12:35:52.629] [INFO] ueberDB - Flushed 4 values
585036 [2020-07-08 12:35:52.743] [WARN] client - Error: Failed assertion: mismatched apply: 7336 / 7368 -- {
585037 errorId: 'msLBpBkLGTRHSnMYbi1M',
585038 msg: 'Error: Failed assertion: mismatched apply: 7336 / 7368',
585039 url: 'https://etherpad.rz.uni-wuerzburg.de/p/g.utrkAfuFX8xB3tuO$WueCampusPads',
585040 linenumber: 13,
585041 userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15'
585042 }
585043 [2020-07-08 12:35:53.228] [INFO] ueberDB - Flushed 4 values
585044 [2020-07-08 12:35:53.430] [INFO] ueberDB - Flushed 4 values
585045 [2020-07-08 12:35:53.458] [WARN] client - Error: Failed assertion: mismatched apply: 7336 / 7369 -- {
585046 errorId: 'vONEfisF3AAjzRROSgl0',
585047 msg: 'Error: Failed assertion: mismatched apply: 7336 / 7369',
585048 url: 'https://etherpad.rz.uni-wuerzburg.de/p/g.utrkAfuFX8xB3tuO$WueCampusPads',
585049 linenumber: 13,
585050 userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15'
585051 }
585052 [2020-07-08 12:35:53.731] [INFO] ueberDB - Flushed 4 values
585053 [2020-07-08 12:35:53.933] [INFO] ueberDB - Flushed 4 values
585054 [2020-07-08 12:35:53.970] [WARN] client - Error: Failed assertion: mismatched apply: 7336 / 7370 -- {
585055 errorId: '9iL1au1keUuh7URxEg77',
585056 msg: 'Error: Failed assertion: mismatched apply: 7336 / 7370',
585057 url: 'https://etherpad.rz.uni-wuerzburg.de/p/g.utrkAfuFX8xB3tuO$WueCampusPads',
585058 linenumber: 13,
585059 userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15'
585060 }

[JohnMcLear]

See the load testing tool and see if you can replicate the bug and let me know your findings. It's really easy to use.