crash due to "mismatched follow"

Crash happened, causing the server to restart (and clients to be disconnected), stack trace:

[2012-02-20 09:48:23.623] [ERROR] console - Error: exports: mismatched follow
at Object.error (/Changeset.js:34:11)
at Object.assert (/Changeset.js:41:13)
at Object.follow (/Changeset.js:1797:11)
at Object.callback (/srv/etherpad-lite/node/handler/PadMessageHandler.js:431:35)
at /srv/etherpad-lite/node_modules/ueberDB/CloneAndAtomicLayer.js:120:17
at /srv/etherpad-lite/node_modules/ueberDB/CacheAndBufferLayer.js:345:7
at [object Object].get (/srv/etherpad-lite/node_modules/ueberDB/CacheAndBufferLayer.js:142:5)
at [object Object].getSub (/srv/etherpad-lite/node_modules/ueberDB/CacheAndBufferLayer.js:317:8)
at [object Object].doOperation as operatorFunction
at [object Object].emit (/srv/etherpad-lite/node_modules/ueberDB/node_modules/channels/channels.js:38:11)
RESTART!

[jrabier]

I can confirm this issue, with a similar stack trace.
I'm using node-v0.6.9 and revision dfa106d for etherpad-lite.

[mrneil]

Like taziden, I had the same error and a similar stack trace this afternoon. I'm running etherpad-lite commit 309e3b0 on node v0.6.11.

Do either of you have logs from the crashes you experienced? The baserev property of the USER_CHANGES messages sent from the users normally increase by one each time. In this case, the baserev of the USER_CHANGES message immediately proceeding the crash went down by one.

By itself, I think that's okay. It just means the change is based on a previous revision (not the latest). But I also see a client-side JS error logged less than 10 seconds earlier. It's a shot in the dark, but logs in other cases where this error occurred may help us determine if there is any relation.

I still have to do some reading up on changesets.

[mrneil]

I replaced PadMessageHandler.js line 431 (in the commit I'm running)

changeset = Changeset.follow(c, changeset, false, apool);

with

try
{
  changeset = Changeset.follow(c, changeset, false, apool);
}
catch(e)
{
  console.warn("Can't apply USER_CHANGES "+changeset+", possibly because of mismatched follow error");
  client.json.send({disconnect:"badChangeset"});
  return;
}

Explanation: Changeset.follow() runs assert() which throws an error if things don't match properly. The try-catch block disconnects the user submitting the mismatch. There's a very similar block about 30 lines above, which is what I based this on.

Feedback is appreciated.

[mrneil]

EDIT - I would ignore this comment as it may have been premature. The issue here seems to be unrelated to the mismatched follow error and the code in my previous comment appears to solve that problem on its own. At the very least, further exploration is required.

Using the test from issue #752, my code catches the mismatched follow error and prevents a crash. However, any user who connects after that will cause a crash ("Cannot convert null to object").

To remedy the new error, I surrounded PadMessageHandler.js lines 713 and 714 with an if statement.

if(author){
delete author.timestamp;
historicalAuthorData[authorId] = author;
}

It works, but I have absolutely no idea what impact it has overall. Run it at your own risk.

And if you can shed any light on the validity of the code, I'm interested in hearing from you.

[JohnMcLear]

Did we ever see a pull request with this fix in?

[mrneil]

No, @johnyma22. I have not created a pull request for two reasons: (a) my lack of familiarity with git and pull requests, and (b) potential impact on other moving parts of Etherpad Lite.

If you or others with experience evaluate the code and determine it to be valid, I have no problem with it being added to the project.

[iamer]

I started seeing this crash frequently with about 10 users, some using older browsers. The two code changes above abolished the crashes. Thank you very much !

A minor side effect is authors sometimes disappear for a short interval and then reappear again.

[mrneil]

Hi @iamer,

I'm glad to know the code works for you! You said you applied two changes, but as I wrote above, you should ignore the second. (I've actually just edited the comment to apply strikethrough text so no one else gets confused.)

The correct code has been running for me without issue for quite a while. We're not seeing authors disappear and reappear, so I wonder what happens if you undo the code change that is (now) crossed out.

[iamer]

I've reverted the spurious change, will keep an eye on the logs and report back. Thanks for your reply.

[JohnMcLear]

I have added a task for myself to review this and issue a pull request after testing.

[iamer]

Now with 30 users I am getting a similar crash, but not sure if it is the same.

[2012-09-11 14:44:03.357] [WARN] socket.io - client not handshaken 'client should reconnect'
[2012-09-11 14:44:11.095] [WARN] socket.io - handshake error Bad session / session has expired
[2012-09-11 14:44:11.787] [WARN] socket.io - handshake error Bad session / session has expired
[2012-09-11 14:44:13.568] [WARN] socket.io - handshake error Bad session / session has expired
[2012-09-11 14:44:18.313] [WARN] socket.io - handshake error Bad session / session has expired
[2012-09-11 14:44:47.818] [ERROR] console - CLIENT SIDE JAVASCRIPT ERROR: {"errorId":"oOnoX0idxIBcIAGjvvgn","msg":"NS_ERROR_FAILURE: Failure","url":"XXX","linenumber":1,"userAgent":"Mozilla/5.0 (Windows NT 6.1; WOW64; rv:14.0) Gecko/20100101 Firefox/14.0.1"}
[2012-09-11 14:44:50.124] [ERROR] console - CLIENT SIDE JAVASCRIPT ERROR: {"errorId":"chOMKbQzwvFEvHp4ZVXv","msg":"NS_ERROR_FAILURE: Failure","url":"XXX","linenumber":1,"userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:15.0) Gecko/20100101 Firefox/15.0"}
[2012-09-11 14:45:06.686] [ERROR] console - CLIENT SIDE JAVASCRIPT ERROR: {"errorId":"BxW92nkuWWtJ0xt1nm2l","msg":"a is null","url":"XXX","linenumber":18,"userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:11.0) Gecko/20100101 Firefox/11.0"}
[2012-09-11 14:45:27.397] [ERROR] console - CLIENT SIDE JAVASCRIPT ERROR: {"errorId":"vpKOzVsuR90JzxuBseql","msg":"TypeError: a is null","url":"XXX","linenumber":18,"userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:15.0) Gecko/20100101 Firefox/15.0"}
[2012-09-11 14:45:34.906] [ERROR] console - CLIENT SIDE JAVASCRIPT ERROR: {"errorId":"Tj9B84xt6Hv1f4nTWZjB","msg":"TypeError: a is null","url":"XXX","linenumber":18,"userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:15.0) Gecko/20100101 Firefox/15.0"}
[2012-09-11 14:45:49.262] [WARN] console - Can't apply USER_CHANGES Z:du8>2|5=1v_e=1|1=1f_f=1|1=17_g=1|1=2c_j=1=1j_a|1+1_a_5_h_7_k+1$
*, possibly because of mismatched follow error
[2012-09-11 14:46:08.222] [ERROR] console - [RangeError: Maximum call stack size exceeded]
Ensure that all dependencies are up to date...
Ensure jQuery is downloaded and up to date...
Clear minfified cache...
ensure custom css/js files are created...
start...

[mrneil]

Just a quick reply for now....

• I see the client not handshaken 'client should reconnect' error on a very regular basis. In my case, I don't seem to get them as often (or sometimes at all) when the user that has poor connectivity is not using EPL that day.
• I can't ever recall seeing the handshake error Bad session / session has expired error you list. Are you doing separate authentication using groups or sessions?
• The NS_ERROR_FAILURE is also new to me.
• I regularly receive the TypeError: a is null message. For me, it usually happens on line 57 though. I haven't determined what exactly is on that line so I don't know what's causing it, although it also seems to occur more frequently with poor connectivity.
• Your mismatched follow error means that it ran the code above and caught the error. Good!
• Finally, the Maximum call stack size exceeded seems eerily similar to issue Reconnect causes error "RangeError: Maximum call stack size exceeded" - detailed #800. But in that case, immediately before the error, I see several hundred NEW_CHANGES messages being sent to a single user as EPL builds and pushes the changesets to bring that user back to the same revision as the others. Unless you've removed a bunch of log entries, it doesn't appear to be the same cause. But I wonder if they are somehow connected.

Have you tried turning DEBUG level logging on? Perhaps it will isolate what is leading to the RangeError.

[iamer]

• I am using external LDAP auth through basic HTTP auth but that's not related to EPL
• I haven't removed any log entries, but logging is not at DEBUG level ( too copious to handle on production with 30+ users hammering EPL)

I will try to write a testing script that replays HTTP traffic and reproduce the bug with debugging turned on.

[marcelklehr]

@amtep I think this was fixed in #1023, wasn't it?

[amtep]

We haven't seen the mismatched follow error since applying the pull request from #1023, but I think the underlying problem hasn't been fixed. The "mismatched follow" would mean that the clients were sending bad changesets and we haven't found an explanation for that.