info command issued after client enters subscriber mode #2037
Description
I've noticed a new issue after upgrading from 5.8.0 to 5.8.2. I believe it's related to #2033.
Here's a self-contained reproduction:
import { Redis } from 'ioredis';
const sub = new Redis();
sub.psubscribe('socket.io#/#*');
sub.subscribe(['socket.io-request#/#', 'socket.io-response#/#', 'socket.io-response#/#3ywmsZ#']);
setTimeout(() => {
sub.psubscribe('socket.io#/external-grading#*');
sub.subscribe([
'socket.io-request#/external-grading#',
'socket.io-response#/external-grading#',
'socket.io-response#/external-grading#TldK34#',
]);
}, 9);The exact timeout will probably have to be tuned to a particular machine, but at least on mine, a 9ms timeout reproduces the following error quite reliably for me:
[ioredis] Unhandled error event: Error: Connection in subscriber mode, only subscriber commands may be used
at EventEmitter.sendCommand (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:338:28)
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:90:25)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:655:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
node:internal/process/promises:394
triggerUncaughtException(err, true /* fromPromise */);
^
Error: Connection in subscriber mode, only subscriber commands may be used
at EventEmitter.sendCommand (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:338:28)
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:90:25)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:655:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
Node.js v24.6.0
I added logs here to try to see what the sequence of events was:
ioredis/lib/utils/Commander.ts
Line 135 in 105dc72
That yielded the following:
Trace: ioredis Commander socket.io#/#* psubscribe psubscribe
at EventEmitter.psubscribe (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at file:///Users/nathan/git/PrairieLearn/apps/prairielearn/redis.mjs:5:5
at ModuleJob.run (node:internal/modules/esm/module_job:371:25)
at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:669:26)
at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)
Trace: ioredis Commander [
'socket.io-request#/#',
'socket.io-response#/#',
'socket.io-response#/#3ywmsZ#'
] subscribe subscribe
at EventEmitter.subscribe (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at file:///Users/nathan/git/PrairieLearn/apps/prairielearn/redis.mjs:6:5
at ModuleJob.run (node:internal/modules/esm/module_job:371:25)
at async onImport.tracePromise.__proto__ (node:internal/modules/esm/loader:669:26)
at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:101:5)
Trace: ioredis Commander SETINFO LIB-NAME ioredis client client
at EventEmitter.client (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at Socket.<anonymous> (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:70:18)
at Object.onceWrapper (node:events:622:28)
at Socket.emit (node:events:520:35)
at afterConnect (node:net:1622:10)
at afterConnectMultiple (node:net:1729:3)
Trace: ioredis Commander SETINFO LIB-VER 5.8.2 client client
at EventEmitter.client (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:65:22
at async Promise.all (index 0)
Trace: ioredis Commander socket.io#/external-grading#* psubscribe psubscribe
at EventEmitter.psubscribe (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at Timeout._onTimeout (file:///Users/nathan/git/PrairieLearn/apps/prairielearn/redis.mjs:9:7)
at listOnTimeout (node:internal/timers:608:17)
at process.processTimers (node:internal/timers:543:7)
Trace: ioredis Commander [
'socket.io-request#/external-grading#',
'socket.io-response#/external-grading#',
'socket.io-response#/external-grading#TldK34#'
] subscribe subscribe
at EventEmitter.subscribe (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at Timeout._onTimeout (file:///Users/nathan/git/PrairieLearn/apps/prairielearn/redis.mjs:10:7)
at listOnTimeout (node:internal/timers:608:17)
at process.processTimers (node:internal/timers:543:7)
Trace: ioredis Commander [Function (anonymous)] info info
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:75:15)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:656:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
Trace: bad command info
at EventEmitter.sendCommand (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:338:23)
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:91:25)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:656:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
[ioredis] Unhandled error event: Error: Connection in subscriber mode, only subscriber commands may be used
at EventEmitter.sendCommand (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:339:28)
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:91:25)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:656:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
node:internal/process/promises:394
triggerUncaughtException(err, true /* fromPromise */);
^
Error: Connection in subscriber mode, only subscriber commands may be used
at EventEmitter.sendCommand (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:339:28)
at EventEmitter.info (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/utils/Commander.js:91:25)
at EventEmitter._readyCheck (/Users/nathan/git/PrairieLearn/node_modules/ioredis/built/Redis.js:656:14)
at /Users/nathan/git/PrairieLearn/node_modules/ioredis/built/redis/event_handler.js:82:22
at <anonymous>
at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
It seems like it tries to issue info commands after the client has already entered subscriber mode.