Init()'ing mysql databases can crash due to broken logging

[cboylan]

We observed this when upgrading from etherpad-lite 1.8.17 to 1.8.18 which updated ueberdb2 from 1.4.18 to 2.2.4. While there is a small chance the issue is in etherpad-lite I strongly suspect euberdb2 and 7a35238 in particular.

When starting etherpad-lite euberDB creates the store table in the database if it doesn't exist, then it checks the charset and collation for the databse and finally the charset and collation for the store table. If the charset is not utf8mb4 and collation not utf8mb4_something then ueberdb logs this message: ueberDB - Database is not configured with charset utf8mb4 -- This may lead to crashes when certain characters are pasted in pads (this is from https://github.com/ether/ueberDB/blob/v2.2.4/databases/mysql_db.js#L76-L77). The problem is what happens next: it tries to log the results of the query for the charset info and then crashes as undefined objects don't have a 'level' property (this happens at https://github.com/ether/ueberDB/blob/v2.2.4/databases/mysql_db.js#L78).

This is what the logs look like from etherpad-lite that illustrate this sequence of events:

[2022-05-09 17:42:55.753] [INFO] server - Starting Etherpad...
[2022-05-09 17:42:55.911] [ERROR] ueberDB - Database is not configured with charset utf8mb4 -- This may lead to crashes when certain characters are pasted in pads
[2022-05-09 17:42:55.912] [ERROR] server - Error occurred while starting Etherpad
[2022-05-09 17:42:55.913] [ERROR] server - Metrics at time of fatal error:
{
  "httpStartTime": 0,
  "memoryUsage": 61227008,
  "memoryUsageHeap": 11458792
}
[2022-05-09 17:42:55.913] [ERROR] server - TypeError: Cannot read property 'level' of undefined
    at Level.isLessThanOrEqualTo (/opt/etherpad-lite/src/node_modules/log4js/lib/levels.js:37:35)
    at Logger.isLevelEnabled (/opt/etherpad-lite/src/node_modules/log4js/lib/logger.js:66:21)
    at Logger.log (/opt/etherpad-lite/src/node_modules/log4js/lib/logger.js:54:13)
    at exports.Database.init (/opt/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:78:19)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
    at async exports.Database.init (/opt/etherpad-lite/src/node_modules/ueberdb2/lib/CacheAndBufferLayer.js:284:5)
    at async Object.exports.init (/opt/etherpad-lite/src/node/db/DB.js:41:3)
    at async Object.exports.start (/opt/etherpad-lite/src/node/server.js:142:5)
[2022-05-09 17:42:55.913] [INFO] server - Exiting...
[2022-05-09 17:42:55.914] [INFO] server - Waiting for Node.js to exit...
[2022-05-09 17:42:56.102] [INFO] plugins - npm --version: 6.14.15

Our etherpad-lite database had default charset and collation set to utf8 which triggers the you aren't set to utf8mb4 path, but on etherpad-lite 1.8.17 with older euberdb this wasn't fatal because we logged it and moved on. The etherpad service itself was happy in that situation because the store table correctly set its charset and collation to the desired values. To work around this problem we altered the etherpad-lite database default charset to utf8mb4 and collation to utf8mb4_bin.

On the eulerdb side of things it should be able to log properly when this problem occurs even if the end result is that etherpad chooses to fail and exit. Additionally, setting these defaults at the database level only appears to affect CREATE TABLE, LOAD DATA, and stored routines in MySQL if they don't explcitly set the charset and collation method. It may not be super important to fail on anyway?

I've just written a lot of words to say I think that logging can crash in the mysql driver causing everything to fail. I'm not entirely sure why though the above commit is suspicious purely due to it touching logging and merging recently.

[SamTV12345]

Is this still an issue in the latest version?

[mitar]

Yes. It happens to me on Etherpad Lite 1.9.3 as well.

The issue is comes from this line:

this.logger.log(result[0], charset);

The issue is that default value for logger is console which has console.log, but Etherpad Lite provides log4js instance for logger, which expects the first argument to log to be the logging level. Because code provides result[0] things fall apart.

I think this is some mismatch in expected API for logger.

[SamTV12345]

Yes. It happens to me on Etherpad Lite 1.9.3 as well.

The issue is comes from this line:

this.logger.log(result[0], charset);

The issue is that default value for logger is console which has console.log, but Etherpad Lite provides log4js instance for logger, which expects the first argument to log to be the logging level. Because code provides result[0] things fall apart.

I think this is some mismatch in expected API for logger.

@mitar So I just need to start Etherpad with a MySQL database and get this error?

[mitar]

@SamTV12345 Yes, but charset/collation has to be utf8 and NOT utf8mb4. Maybe if you put into settings.json "charset": "utf8" it should happen. In my case (and I suspect others experiencing this) this happens because we have old MySQL databases with utf8 charset.

See also: YunoHost-Apps/etherpad_mypads_ynh#172

[SamTV12345]

Hm. I can't even get it to work with MySQL. I get this error: [2023-10-11 21:23:03.581] [ERROR] ueberDB - Fatal MySQL error: Error: ER_ACCESS_DENIED_ERROR: Access denied for user 'etherpaduser'@'192.168.65.1' (using password: YES)

This is my settings json:

  "dbType" : "mysql",
  "dbSettings" : {
    "user":     "etherpaduser",
    "host":     "localhost",
    "port":     3306,
    "password": "password",
    "database": "etherpad_lite_db",
    "charset":  "utf8mb4"
  },

and my docker compose:

version: '3'
services:
db:
   image: mysql
   ports:
     - 3306:3306
   environment:
     MYSQL_ROOT_PASSWORD: password
     MYSQL_USER: ueberdb
     MYSQL_PASSWORD: ueberdb
     MYSQL_DATABASE: ueberdb

[mitar]

Hm, your MYSQL_USER does not match "user" and MYSQL_PASSWORD does not match "password"? So I am not surprised that it does not work?

[SamTV12345]

I forgot to mention. The issue is resolved on the develop tag.