Fatal ioredis error: "Command queue state error" caused by Hocuspocus pub/sub messages

[matteotarantino-algor]

Description

We’re experiencing recurring crashes caused by an uncaught exception thrown inside ioredis, specifically this error:

{
    "level": "err",
    "message": "Process shutting down",
    "metadata": {
        "reason": "uncaughtException",
        "error": {
            "message": "Command queue state error. If you can reproduce this, please report it. Last reply: message,hocuspocus::69306d66030152471d5feac7,\u0019hocuspocus-10.0.29.163:33\u001869306d66030152471d5feac7\u0001\f\u0001\ufffd\ufffd\ufffd\ufffd\u000e\u0002\u0004null",
            "stack": "Error: Command queue state error. If you can reproduce this, please report it. Last reply: message,hocuspocus::69306d66030152471d5feac7,\u0019hocuspocus-10.0.29.163:33\u001869306d66030152471d5feac7\u0001\f\u0001\ufffd\ufffd\ufffd\ufffd\u000e\u0002\u0004null\n    at DataHandler.shiftCommand (/usr/src/app/hocuspocus-be/hocuspocus-be/node_modules/ioredis/built/DataHandler.js:180:27)\n    at DataHandler.returnReply (/usr/src/app/hocuspocus-be/hocuspocus-be/node_modules/ioredis/built/DataHandler.js:57:27)\n    at JavascriptRedisParser.returnReply (/usr/src/app/hocuspocus-be/hocuspocus-be/node_modules/ioredis/built/DataHandler.js:21:22)\n    at JavascriptRedisParser.execute (/usr/src/app/hocuspocus-be/hocuspocus-be/node_modules/redis-parser/lib/parser.js:544:14)\n    at TLSSocket.<anonymous> (/usr/src/app/hocuspocus-be/hocuspocus-be/node_modules/ioredis/built/DataHandler.js:26:20)\n    at TLSSocket.emit (node:events:518:28)\n    at TLSSocket.emit (node:domain:489:12)\n    at TLSSocket.Readable.read (node:internal/streams/readable:782:10)\n    at TLSSocket.Socket.read (node:net:777:39)\n    at flow (node:internal/streams/readable:1283:53)"
        }
    }
}

The error seems to originate from a pub/sub message (Last reply: message,hocuspocus::<docId>,…) being processed when the internal commandQueue is unexpectedly empty. This leads to a fatal error event emitted by ioredis, which then becomes an uncaughtException and crashes the Hocuspocus worker.

This is happening intermittently in production and results in the worker being force-restarted by our process manager.

Environment?

• ioredis: 5.8.2
• redis: AWS Valkey Elasticache Serverless
• Hocuspocus version: 3.4.0

[matteotarantino-algor]

Any news about that?
@janthurau

It might be the root cause of the spikes on the CPU of this kind

[udacosta-gp]

Had a similar issue with the redis extension. In my case, this was cause by the onAwarenessUpdate hook when the count of connected clients dropped to 0 on a document. The hook tries to createAwarenessUpdateMessage to the "changedClients" but there are no connections left and this generates a malformed message that triggers an exception (there really is no need to try and send a message to a document that no longer has connections and is potentially offloaded). This fixed it for me:

async onAwarenessUpdate({ documentName, awareness, added, updated, removed }: onAwarenessUpdatePayload) {
    //  added this escape if document no longer has connections
    const document = this.instance.documents.get(documentName);
    const connections = document?.connections.size || 0; // suppress
    if (connections === 0) {
      return; // avoids exception
    }

    // otherwise, emit message with awareness update normally
    try {
      const changedClients = added.concat(updated, removed);
      const message = new OutgoingMessage(documentName).createAwarenessUpdateMessage(awareness, changedClients);
      return this.pub.publish(this.pubKey(documentName), this.encodeMessage(message.toUint8Array()));
    } catch (error) {
      info('Error in onAwarenessUpdate:', 'system', { Error: error.message });
    }
  }

[matteotarantino-algor]

Confirmed that this is the error @udacosta-gp, thanks!

@janthurau

I opened this pull request which includes a fix for the problem (tested on my side).
Note: it also resolves an additional bug related to onStoreDocument, although that one is not directly connected to this issue.

Let me know if you have an estimated timeline for publishing the fix, it’s quite urgent for us. Thanks!