Maximum call stack size exceeded

[mifopen]

It looks like there is an infinite loop in one of the possible scenarios: ServerClient.destroy() => custom unsubscribe() => log.add => send => 'WS was closed' => LoguxServer.debugError => send => 'WS was closed' => debugError => send => ... Facts that we can observe:

1. Tons of this in logs before the "Maximum call stack size exceeded" error

[error][logux] {
  err: {
    message: 'WS was closed',
    name: 'Error',
    stack: 'Error: WS was closed\n' +
      '    at ServerConnection.send (file:///Users/me/src/node_modules/@logux/core/ws-connection/index.js:72:34)\n' +
      '    at LoguxServerWithQueues.debugError (file:///Users/me/src/node_modules/@logux/server/base-server/index.js:525:24)\n' +
      '    at file:///Users/me/src/node_modules/@logux/server/base-server/index.js:270:44\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at file:///Users/me/src/node_modules/@logux/server/server-client/index.js:49:24\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at FilteredNode.error (file:///Users/me/src/node_modules/@logux/core/base-node/index.js:233:18)\n' +
      '    at file:///Users/me/src/node_modules/@logux/core/base-node/index.js:100:16\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at ServerConnection.send (file:///Users/me/src/node_modules/@logux/core/ws-connection/index.js:72:20)\n' +
      '    at LoguxServerWithQueues.debugError (file:///Users/me/src/node_modules/@logux/server/base-server/index.js:525:24)\n' +
      '    at file:///Users/me/src/node_modules/@logux/server/base-server/index.js:270:44\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at file:///Users/me/src/node_modules/@logux/server/server-client/index.js:49:24'
  },
  connectionId: '18'
} WS was closed

2. Followed by this:

[info][logux] { actionId: '1651273880706 server:-yGQOYF5 0', channel: 'menu/11' } Client was unsubscribed
[info][logux] { nodeId: '70:xbPqR9RG:S5VraEMz' } Client was disconnected
[fatal][logux] {
  err: {
    message: 'Maximum call stack size exceeded',
    name: 'RangeError',
    stack: 'RangeError: Maximum call stack size exceeded\n' +
      '    at formatRaw (node:internal/util/inspect:1037:12)\n' +
      '    at formatValue (node:internal/util/inspect:817:10)\n' +
      '    at inspect (node:internal/util/inspect:347:10)\n' +
      '    at formatWithOptionsInternal (node:internal/util/inspect:2167:40)\n' +
      '    at formatWithOptions (node:internal/util/inspect:2029:10)\n' +
      '    at console.value (node:internal/console/constructor:324:14)\n' +
      '    at console.log (node:internal/console/constructor:360:61)\n' +
      '    at Object.info (file:///Users/me/src/log.ts:20:36)\n' +
      '    at reporter (file:///Users/me/src/node_modules/@logux/server/create-reporter/index.js:245:27)\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at file:///Users/me/src/node_modules/@logux/server/base-server/index.js:176:20\n' +
      '    at file:///Users/me/src/node_modules/nanoevents/index.js:4:46\n' +
      '    at Array.forEach (<anonymous>)\n' +
      '    at Object.emit (file:///Users/me/src/node_modules/nanoevents/index.js:4:33)\n' +
      '    at actionEvents (file:///Users/me/src/node_modules/@logux/core/log/index.js:8:11)\n' +
      '    at Log.add (file:///Users/me/src/node_modules/@logux/core/log/index.js:96:7)\n' +
      '    at Object.unsubscribe (file:///Users/me/src/modules/appEditor.ts:349:18)\n' +
      '    at Object.subscribers.<computed>.<computed>.unsubscribe (file:///Users/me/src/node_modules/@logux/server/base-server/index.js:746:27)\n' +
      '    at LoguxServerWithQueues.performUnsubscribe (file:///Users/me/src/node_modules/@logux/server/base-server/index.js:790:22)\n' +
      '    at ServerClient.destroy (file:///Users/me/src/node_modules/@logux/server/server-client/index.js:92:20)'
  }
} Maximum call stack size exceeded
[info][logux] {} Shutting down Logux server

3. I've injected some code into WsConnection class and can say that a. "WS was closed" is happening because this.ws.readyState === closing b. there is no calls to ws.onerror or ws.onclose or this.disconnect before

As I understand it's a normal situation that WS connection can stuck in a closing state and that's why we need heartbeats. But I don't understand how to reproduce it. Can only say that it's happening regularly if I just leave my laptop for some (or close it)

[ai]

Thanks for the issue with many details.

I will try to investigate today or tomorrow.

[ai]

Hi. Sorry, I just found a time to review.

I found two strange things:

1. The non-standard log output
2. Non-Logux file src/log.ts in the stacktrace

What is Loguc Server options? What changes to the logger did you applied? Can you show src/log.ts content?