Log floods with different error logs since 1.9.0

[0x46616c6b]

Describe the bug

The log file is full of different error messages from PadMessageHandler.js.

Example:

Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.694] [ERROR] socket.io - Error handling pad message from nQBC3cswC4Bfxq3mAABw: Error: client disconnected
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:322:54)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14
Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.694] [ERROR] socket.io - Error handling pad message from 5KsBnpuk99mGi3K8AAAy: Error: client disconnected
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:322:54)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14
Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.695] [ERROR] socket.io - Error handling pad message from ZKH3EfXRbZhWd40QAAAN: Error: client disconnected
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:322:54)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14
Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.896] [ERROR] socket.io - Error handling pad message from JGiR3GuJFd4TDGCSAABt: Error: COLLABROOM: USERINFO_UPDATE: malformed color: false
Jul 01 18:23:33 etherpad1 node[2795824]:     at handleUserInfoUpdate (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:516:11)
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:338:43)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14
Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.993] [ERROR] socket.io - Error handling pad message from 23DryGqhKGkW7z3KAABy: Error: COLLABROOM: USERINFO_UPDATE: malformed color: false
Jul 01 18:23:33 etherpad1 node[2795824]:     at handleUserInfoUpdate (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:516:11)
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:338:43)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14
Jul 01 18:23:36 etherpad1 node[2795824]: [2023-07-01 18:23:36.597] [ERROR] socket.io - Error handling pad message from EREEUBUwVQza92BiAABz: Error: COLLABROOM: USERINFO_UPDATE: malformed color: false
Jul 01 18:23:36 etherpad1 node[2795824]:     at handleUserInfoUpdate (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:516:11)
Jul 01 18:23:36 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:338:43)
Jul 01 18:23:36 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:36 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14

To Reproduce
Steps to reproduce the behavior:

1. Install Etherpad >= 1.9.0
2. Use it
3. Look in the log file

Expected behavior

No error log

Server (please complete the following information):

• Etherpad version: 1.9.1
• OS: Debian Bullseye
• Node.js version (node --version): v14.21.3
• npm version (npm --version): 6.14.18
• Is the server free of plugins: no

[webzwo0i]

Probably multiple bugs.

The later (USERINFO_UPDATE) might be a client issue, e.g. a problem parsing the colorId so it's set to false and server behavior is correct.

The former could be a number of things, e.g. clients that can't connect (would be a major issue).

What plugins are in use? ep_table_of_contents, ep_httpauth_author, ep_delete_after_delay, ep_headerauth?

[webzwo0i]

Indeed on your instance the client transmits a username "false" and a colorId "false", unless the user chooses a new color. So I assume there's a problem with one of the installed plugins

[0x46616c6b]

That are our installed plugins:

• ep_comments_page
• ep_headings2
• ep_markdown
• ep_scrolltoanchor
• ep_spellcheck
• ep_table_of_contents

[0x46616c6b]

From client perspective it looks like this:

[duckinator]

My girlfriend ran into the malformed color: false problem, and it appears to be caused by using a settings.json file from a pre-v1.9.0 version.

To fix the problem, she modified settings.json and changed the following values under padOptions from false to null:

1. userName
2. userColor

While helping debug this, I determined that:

1. Authorship in editor displayed incorrectly (as "false") after update #5401 appears to be the same bug.
2. pad: Fix application of padOptions values from settings.json #5313, and in particular 8c857a8, updated the default values. That's why new v1.9.0+ instances don't have the same problem.

[webzwo0i]

Great, thanks!

Does this also cause the first stack traces with Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:322:54) ?

[0x46616c6b]

I set the options userName and userColor to null and it solves this kind of error messages

Jul 01 18:23:33 etherpad1 node[2795824]: [2023-07-01 18:23:33.993] [ERROR] socket.io - Error handling pad message from 23DryGqhKGkW7z3KAABy: Error: COLLABROOM: USERINFO_UPDATE: malformed color: false
Jul 01 18:23:33 etherpad1 node[2795824]:     at handleUserInfoUpdate (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:516:11)
Jul 01 18:23:33 etherpad1 node[2795824]:     at Object.exports.handleMessage (/home/etherpad/etherpad-lite/src/node/handler/PadMessageHandler.js:338:43)
Jul 01 18:23:33 etherpad1 node[2795824]:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Jul 01 18:23:33 etherpad1 node[2795824]:     at async /home/etherpad/etherpad-lite/src/node/handler/SocketIORouter.js:76:14

The [ERROR] socket.io - Error handling pad message from <REDACTED>: Error: client disconnected is still present

[webzwo0i]

Do you still experience the same amount of 'client disconnected' errors as you did after updating? Did any of your users report problems using Etherpad?

The relevant PR is probably https://github.com/ether/etherpad-lite/pull/5431/files but I was unable to reproduce under normal conditions. Do you only see errors like Error: client disconnected - without something like USER_CHANGES in the error message? Because under normal conditions it would be more likely that a session is gone, while the message is still being processed, but this would result in a slightly different error message.
The client disconnected error happens if after receiving but before processing the request with the correct handler the session disappears. The ep_comments plugin registers a hook (handleMessageSecurity), so if you're instance is under high load, events could accumulate and after they are processed by the hook, the session is already gone. In theory, this might explain why the errors are printed consecutively in a very short time frame.
However, the hook does no expensive computation, so it's unlikely that this would happen over a larger period of time.

I noticed you are using node v14. Recommended is at least v16 and the above tests were done with v16.

If we are sure this is not an error but only too verbose logging, we can change it to info logging, while keeping the exception handling as it is.

[0x46616c6b]

I can confirm that the Error: client disconnected are really rare now. So for me it seems to be fixed. I will test the Update to node v16 soon.

Edit: Also with Node 16 it seems only appear after restart and when I directly try to access a Pad. After some time it looks good.

[webzwo0i]

OK, thanks for the feedback. Let's keep this open for some weeks in case others encounter the same problem as not everybody has updated yet, but it probably indicates no severe issue.
However, no root cause could be found.