etherpad-lite: Etherpad crashs when querying stats API with timeout

Describe the bug

We wrote a Prometheus Exporter for Etherpad which aggregates the metrics from /stats and if an api key is configured also the getStats data from the API. The exporter runs independently and greps every 15 seconds the data from Etherpad. After Etherpad restarted the API call takes more time and run into a timeout which kills Etherpad entirely. So you end up into a endless crashloop until the exporter is stopped or no timeout is configured.

To Reproduce Steps to reproduce the behavior:

  1. Start Etherpad
  2. Trigger the API Endpoint getStats with a “short” timeout

Expected behavior

Etherpad should not crash if the HTTP Client closes the connection to the API Endpoint.

Server (please complete the following information):

  • Etherpad version: 1.8.13
  • OS: Debian Buster
  • Node.js version (node --version): v14.16.1
  • npm version (npm --version): 6.14.12

Additional context

Apr 12 23:22:22 etherpad1 systemd[1]: Started Etherpad-lite, the collaborative editor..
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[36m[2021-04-12 23:22:22.373] [DEBUG] console - #033[39mRunning on Node v14.16.1 (minimum required Node version: 10.17.0)
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[32m[2021-04-12 23:22:22.491] [INFO] console - #033[39mAll relative paths will be interpreted relative to the identified Etherpad base dir: /home/etherpad/etherpad-lite
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[36m[2021-04-12 23:22:22.492] [DEBUG] AbsolutePaths - #033[39mRelative path "settings.json" can be rewritten to "/home/etherpad/etherpad-lite/settings.json"
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[36m[2021-04-12 23:22:22.493] [DEBUG] AbsolutePaths - #033[39mRelative path "credentials.json" can be rewritten to "/home/etherpad/etherpad-lite/credentials.json"
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[32m[2021-04-12 23:22:22.501] [INFO] console - #033[39msettings loaded from: /home/etherpad/etherpad-lite/settings.json
Apr 12 23:22:22 etherpad1 nodejs[24651]: #033[32m[2021-04-12 23:22:22.503] [INFO] console - #033[39mNo credentials file found in /home/etherpad/etherpad-lite/credentials.json. Ignoring.
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.800] [ERROR] API - #033[39mError: Query inactivity timeout
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.<anonymous> (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:160:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.emit (events.js:315:20)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.EventEmitter.emit (domain.js:467:12)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/sequences/Sequence.js:124:8)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Timer._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Timer.js:32:23)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at listOnTimeout (internal/timers.js:554:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at processTimers (internal/timers.js:497:7)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     --------------------
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Protocol._enqueue (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:144:48)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Connection.query (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/Connection.js:198:25)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at /home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:48:22
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at new Promise (<anonymous>)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database._query (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:47:16)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:166:32)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/lib/CacheAndBufferLayer.js:350:42)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at bound Callbackified (util.js:210:5)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/index.js:101:51)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at internal/util.js:297:30
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.810] [ERROR] server - #033[39mMetrics at time of fatal error:
Apr 12 23:27:22 etherpad1 nodejs[24651]: {
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "httpStartTime": 1618262554613,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "memoryUsage": 150118400,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "memoryUsageHeap": 42279784,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockAwaits": 227,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockAcquires": 4102,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockReleases": 4102,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_reads": 3398,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFailed": 7,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFinished": 3398,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromCache": 2712,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDb": 686,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDbFailed": 7,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDbFinished": 686,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writes": 936,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesFailed": 40,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesFinished": 935,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesObsoleted": 3,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDb": 932,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDbFailed": 38,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDbFinished": 932,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "totalUsers": 25,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "connects": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 0.19437756269899367,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 56,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 0.11080503449773703,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0.1454285109645706,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0.1113325156778778,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0.05130874060504336
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "activePads": 16,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "httpRequests": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "meter": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 0.3314206817950703,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 95,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "currentRate": 0.22161061538467536,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "1MinuteRate": 0.3108332413113748,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "5MinuteRate": 0.19988191174528958,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "15MinuteRate": 0.0891161297661651
Apr 12 23:27:22 etherpad1 nodejs[24651]:     },
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "histogram": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "min": 0.5807790756225586,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "max": 68821.29880619049,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "sum": 71049.93284893036,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "variance": 49831069.57536029,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 747.8940299887406,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "stddev": 7059.112520378202,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 95,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "median": 2.101907730102539,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p75": 11.942557334899902,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p95": 171.75158967971748,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p99": 68821.29880619049,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p999": 68821.29880619049
Apr 12 23:27:22 etherpad1 nodejs[24651]:     }
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "lastDisconnect": 1618262842809,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "disconnects": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 0.11005730569279114,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 31,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 0.11080851535320309,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0.1324211065862349,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0.07215982332224166,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0.030373680109399774
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "pendingEdits": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "edits": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "meter": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 0.7968765178628363,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 188,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "currentRate": 0.11080867731052062,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "1MinuteRate": 0.3074159454773949,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "5MinuteRate": 0.3729894875325836,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "15MinuteRate": 0.17457683880165267
Apr 12 23:27:22 etherpad1 nodejs[24651]:     },
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "histogram": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "min": 6.889542102813721,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "max": 68831.67011594772,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "sum": 88935.45752716064,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "variance": 25125555.822464745,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 473.06094429340766,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "stddev": 5012.539857444003,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 188,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "median": 103.0302345752716,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p75": 105.16710209846497,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p95": 132.28954513072966,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p99": 8321.396875781007,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p999": 68831.67011594772
Apr 12 23:27:22 etherpad1 nodejs[24651]:     }
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "failedChangesets": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 72.33224008162155,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 1,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 72.35291282513023,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0
Apr 12 23:27:22 etherpad1 nodejs[24651]:   }
Apr 12 23:27:22 etherpad1 nodejs[24651]: }
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.810] [ERROR] server - #033[39mError: Query inactivity timeout
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.<anonymous> (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:160:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.emit (events.js:315:20)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.EventEmitter.emit (domain.js:467:12)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/sequences/Sequence.js:124:8)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Timer._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Timer.js:32:23)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at listOnTimeout (internal/timers.js:554:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at processTimers (internal/timers.js:497:7)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     --------------------
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Protocol._enqueue (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:144:48)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Connection.query (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/Connection.js:198:25)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at /home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:48:22
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at new Promise (<anonymous>)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database._query (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:47:16)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:166:32)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/lib/CacheAndBufferLayer.js:350:42)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at bound Callbackified (util.js:210:5)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/index.js:101:51)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at internal/util.js:297:30
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.835] [ERROR] server - #033[39mMetrics at time of fatal error:
Apr 12 23:27:22 etherpad1 nodejs[24651]: {
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "httpStartTime": 1618262554613,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "memoryUsage": 106090496,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "memoryUsageHeap": 42580640,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockAwaits": 227,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockAcquires": 4119,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_lockReleases": 4119,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_reads": 3415,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFailed": 7,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFinished": 3415,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromCache": 2729,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDb": 686,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDbFailed": 7,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_readsFromDbFinished": 686,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writes": 936,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesFailed": 41,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesFinished": 936,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesObsoleted": 3,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDb": 933,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDbFailed": 39,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "ueberdb_writesToDbFinished": 933,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "totalUsers": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "connects": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 0.1943604122224456,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 56,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0.1454285109645706,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0.1113325156778778,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0.05130874060504336
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "activePads": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "httpRequests": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "meter": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 0.33139130915184495,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 95,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "currentRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "1MinuteRate": 0.3108332413113748,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "5MinuteRate": 0.19988191174528958,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "15MinuteRate": 0.0891161297661651
Apr 12 23:27:22 etherpad1 nodejs[24651]:     },
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "histogram": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "min": 0.5807790756225586,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "max": 68821.29880619049,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "sum": 71049.93284893036,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "variance": 49831069.57536029,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 747.8940299887406,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "stddev": 7059.112520378202,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 95,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "median": 2.101907730102539,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p75": 11.942557334899902,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p95": 171.75158967971748,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p99": 68821.29880619049,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p999": 68821.29880619049
Apr 12 23:27:22 etherpad1 nodejs[24651]:     }
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "lastDisconnect": 1618262842835,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "disconnects": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 0.19879525532846254,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 56,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 983.4321927584721,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0.1324211065862349,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0.07215982332224166,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0.030373680109399774
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "pendingEdits": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "edits": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "meter": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 0.7967906625475465,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 188,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "currentRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "1MinuteRate": 0.3074159454773949,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "5MinuteRate": 0.3729894875325836,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "15MinuteRate": 0.17457683880165267
Apr 12 23:27:22 etherpad1 nodejs[24651]:     },
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "histogram": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "min": 6.889542102813721,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "max": 68831.67011594772,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "sum": 88935.45752716064,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "variance": 25125555.822464745,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "mean": 473.06094429340766,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "stddev": 5012.539857444003,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "count": 188,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "median": 103.0302345752716,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p75": 105.16710209846497,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p95": 132.28954513072966,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p99": 8321.396875781007,
Apr 12 23:27:22 etherpad1 nodejs[24651]:       "p999": 68831.67011594772
Apr 12 23:27:22 etherpad1 nodejs[24651]:     }
Apr 12 23:27:22 etherpad1 nodejs[24651]:   },
Apr 12 23:27:22 etherpad1 nodejs[24651]:   "failedChangesets": {
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "mean": 25.473522963427094,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "count": 1,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "currentRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "1MinuteRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "5MinuteRate": 0,
Apr 12 23:27:22 etherpad1 nodejs[24651]:     "15MinuteRate": 0
Apr 12 23:27:22 etherpad1 nodejs[24651]:   }
Apr 12 23:27:22 etherpad1 nodejs[24651]: }
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.838] [ERROR] server - #033[39mError: Query inactivity timeout
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.<anonymous> (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:160:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.emit (events.js:315:20)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query.EventEmitter.emit (domain.js:467:12)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Query._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/sequences/Sequence.js:124:8)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Timer._onTimeout (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Timer.js:32:23)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at listOnTimeout (internal/timers.js:554:17)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at processTimers (internal/timers.js:497:7)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     --------------------
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Protocol._enqueue (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/protocol/Protocol.js:144:48)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at Connection.query (/home/etherpad/etherpad-lite/src/node_modules/mysql/lib/Connection.js:198:25)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at /home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:48:22
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at new Promise (<anonymous>)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database._query (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:47:16)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/databases/mysql_db.js:166:32)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/lib/CacheAndBufferLayer.js:350:42)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at bound Callbackified (util.js:210:5)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at exports.Database.findKeys (/home/etherpad/etherpad-lite/src/node_modules/ueberdb2/index.js:101:51)
Apr 12 23:27:22 etherpad1 nodejs[24651]:     at internal/util.js:297:30
Apr 12 23:27:22 etherpad1 nodejs[24651]: #033[31m[2021-04-12 23:27:22.838] [ERROR] server - #033[39mError occurred while waiting to exit. Forcing an immediate unclean exit...

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 16 (14 by maintainers)

Most upvoted comments

OK, this is also what I saw with a queryTimeout of 1-10 ms. So it’s probably what @dcht00 experiences.

Let’s wait if @rhansen has time to review the PR, which will hopefully stop Etherpad from crashing.