ioredis: Cluster: Failed to refresh slots cache. when options.redisOptions.enableOfflineQueue = false
If I pass options to new Cluster with options.redisOptions.enableOfflineQueue = false, ioredis (3.2.2) fails to connect to the cluster. If I remove setting that specific option, then everything is good (went through them one-by-one).
Below is sample code with the output when options.redisOptions.enableOfflineQueue = false.
Note that I also have set options.enableOfflineQueue = false - it is not entirely clear if both need to be set. In my usage, I do NOT want commands to be queued when the cluster or the intended node is not available.
'use strict';
let Redis = require('ioredis');
function _retryStrategy(times) {
let retry;
if (times === 1) {
retry = 1; // immediate retry
} else {
retry = Math.min((times - 1) * 2000, 20000);
}
return retry;
}
const options = {
// Cluster-level options
// Override ioredis defaults.
clusterRetryStrategy : _retryStrategy,
enableOfflineQueue : false, // ioredis default is true
scaleReads : 'all', // ioredis default is 'master'
// ioredis defaults - explicitly set for clarity.
enableReadyCheck : true,
maxRedirections : 16,
retryDelayOnFailover : 100,
retryDelayOnClusterDown: 100,
retryDelayOnTryAgain : 100,
// Per Server options
redisOptions: {
// Override ioredis defaults.
enableOfflineQueue : false, // ioredis default is true !!! THIS IS THE PROBLEM !!!
connectTimeout : 2000, // ioredis default is 10000
autoResendUnfulfilledCommands: false, // ioredis default is true
retryStrategy : _retryStrategy,
readOnly : true, // ioredis default is false
// ioredis defaults - explicitly set for clarity.
family : 4,
path : null,
keepAlive : 0,
noDelay : true,
db : 0,
dropBufferSupport: false,
enableReadyCheck : true,
autoResubscribe : true,
lazyConnect : false,
keyPrefix : '',
stringNumbers : false
}
};
let startupNodes = [];
for (let i = 0; i < 3; i++) {
startupNodes[i] = {
host: '127.0.0.1',
port: 6400 + (10*i)
};
console.log('Using startupNode %s:%d.', startupNodes[i].host, startupNodes[i].port);
}
let client = new Redis.Cluster(startupNodes, options);
client.on('ready', function() {
console.log('Redis Cluster is Ready.');
});
client.cluster('info', function (err, clusterInfo) {
if (err) {
console.log('Redis Cluster is not yet ready. err=%j', err);
} else {
console.log('Redis Cluster Info=%j', clusterInfo);
}
});
/usr/src/app# DEBUG=ioredis:* node clustertest.js
Using startupNode 127.0.0.1:6400.
Using startupNode 127.0.0.1:6410.
Using startupNode 127.0.0.1:6420.
ioredis:cluster status: [empty] -> connecting +0ms
ioredis:redis status[127.0.0.1:6400]: [empty] -> connecting +3ms
ioredis:redis status[127.0.0.1:6410]: [empty] -> connecting +2ms
ioredis:redis status[127.0.0.1:6420]: [empty] -> connecting +0ms
ioredis:cluster getting slot cache from 127.0.0.1:6410 +1ms
ioredis:redis status[127.0.0.1:6400]: connecting -> connect +15ms
ioredis:redis write command[0] -> info() +0ms
ioredis:redis status[127.0.0.1:6410]: connecting -> connect +2ms
ioredis:redis write command[0] -> info() +0ms
ioredis:redis status[127.0.0.1:6420]: connecting -> connect +1ms
ioredis:redis write command[0] -> info() +0ms
ioredis:cluster getting slot cache from 127.0.0.1:6420 +3ms
Redis Cluster is not yet ready. err={}
ioredis:cluster getting slot cache from 127.0.0.1:6400 +2ms
[ioredis] Unhandled error event: Error: Failed to refresh slots cache.
at tryNode (/usr/src/app/node_modules/ioredis/lib/cluster/index.js:375:19)
at /usr/src/app/node_modules/ioredis/lib/cluster/index.js:387:9
at /usr/src/app/node_modules/ioredis/lib/cluster/index.js:591:14
at run (/usr/src/app/node_modules/ioredis/lib/utils/index.js:153:16)
at tryCatcher (/usr/src/app/node_modules/bluebird/js/release/util.js:16:23)
at Promise.errorAdapter [as _rejectionHandler0] (/usr/src/app/node_modules/bluebird/js/release/nodeify.js:35:34)
at Promise._settlePromise (/usr/src/app/node_modules/bluebird/js/release/promise.js:566:21)
at Promise._settlePromise0 (/usr/src/app/node_modules/bluebird/js/release/promise.js:614:10)
at Promise._settlePromises (/usr/src/app/node_modules/bluebird/js/release/promise.js:689:18)
at Async._drainQueue (/usr/src/app/node_modules/bluebird/js/release/async.js:133:16)
at Async._drainQueues (/usr/src/app/node_modules/bluebird/js/release/async.js:143:10)
at Immediate.Async.drainQueues (/usr/src/app/node_modules/bluebird/js/release/async.js:17:14)
at runCallback (timers.js:789:20)
at tryOnImmediate (timers.js:751:5)
at processImmediate [as _immediateCallback] (timers.js:722:5)
ioredis:redis status[127.0.0.1:6410]: connect -> ready +7ms
ioredis:redis status[127.0.0.1:6420]: connect -> ready +2ms
ioredis:redis status[127.0.0.1:6420]: ready -> close +1ms
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:6420]: close -> end +0ms
ioredis:redis status[127.0.0.1:6410]: ready -> close +1ms
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:6410]: close -> end +0ms
ioredis:redis status[127.0.0.1:6400]: connect -> ready +1ms
ioredis:redis status[127.0.0.1:6400]: ready -> close +0ms
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:6400]: close -> end +1ms
ioredis:cluster status: connecting -> close +0ms
ioredis:cluster status: close -> reconnecting +1ms
ioredis:cluster Cluster is disconnected. Retrying after 1ms +2ms
ioredis:cluster status: reconnecting -> connecting +0ms
ioredis:redis status[127.0.0.1:6400]: [empty] -> connecting +1ms
ioredis:redis status[127.0.0.1:6410]: [empty] -> connecting +1ms
ioredis:redis status[127.0.0.1:6420]: [empty] -> connecting +1ms
ioredis:cluster getting slot cache from 127.0.0.1:6410 +0ms
ioredis:redis status[127.0.0.1:6400]: connecting -> connect +3ms
ioredis:redis write command[0] -> info() +1ms
ioredis:redis status[127.0.0.1:6410]: connecting -> connect +0ms
ioredis:redis write command[0] -> info() +0ms
ioredis:redis status[127.0.0.1:6420]: connecting -> connect +1ms
ioredis:redis write command[0] -> info() +0ms
ioredis:cluster getting slot cache from 127.0.0.1:6420 +0ms
ioredis:cluster getting slot cache from 127.0.0.1:6400 +1ms
[ioredis] Unhandled error event: Error: Failed to refresh slots cache.
at tryNode (/usr/src/app/node_modules/ioredis/lib/cluster/index.js:375:19)
at /usr/src/app/node_modules/ioredis/lib/cluster/index.js:387:9
at /usr/src/app/node_modules/ioredis/lib/cluster/index.js:591:14
at run (/usr/src/app/node_modules/ioredis/lib/utils/index.js:153:16)
at tryCatcher (/usr/src/app/node_modules/bluebird/js/release/util.js:16:23)
at Promise.errorAdapter [as _rejectionHandler0] (/usr/src/app/node_modules/bluebird/js/release/nodeify.js:35:34)
at Promise._settlePromise (/usr/src/app/node_modules/bluebird/js/release/promise.js:566:21)
at Promise._settlePromise0 (/usr/src/app/node_modules/bluebird/js/release/promise.js:614:10)
at Promise._settlePromises (/usr/src/app/node_modules/bluebird/js/release/promise.js:689:18)
at Async._drainQueue (/usr/src/app/node_modules/bluebird/js/release/async.js:133:16)
at Async._drainQueues (/usr/src/app/node_modules/bluebird/js/release/async.js:143:10)
at Immediate.Async.drainQueues (/usr/src/app/node_modules/bluebird/js/release/async.js:17:14)
at runCallback (timers.js:789:20)
at tryOnImmediate (timers.js:751:5)
at processImmediate [as _immediateCallback] (timers.js:722:5)
ioredis:redis status[127.0.0.1:6410]: connect -> ready +7ms
ioredis:redis status[127.0.0.1:6410]: ready -> close +1ms
ioredis:connection skip reconnecting since the connection is manually closed. +1ms
ioredis:redis status[127.0.0.1:6410]: close -> end +0ms
ioredis:redis status[127.0.0.1:6400]: connect -> ready +4ms
ioredis:redis status[127.0.0.1:6420]: connect -> ready +1ms
ioredis:redis status[127.0.0.1:6420]: ready -> close +0ms
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:6420]: close -> end +1ms
ioredis:redis status[127.0.0.1:6400]: ready -> close +0ms
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:6400]: close -> end +0ms
ioredis:cluster status: connecting -> close +0ms
ioredis:cluster status: close -> reconnecting +1ms
^C
If I comment out the one line, then all is good:
/usr/src/app# DEBUG=ioredis:* node clustertest.js
Using startupNode 127.0.0.1:6400.
Using startupNode 127.0.0.1:6410.
Using startupNode 127.0.0.1:6420.
ioredis:cluster status: [empty] -> connecting +0ms
ioredis:redis status[127.0.0.1:6400]: [empty] -> connecting +3ms
ioredis:redis status[127.0.0.1:6410]: [empty] -> connecting +3ms
ioredis:redis status[127.0.0.1:6420]: [empty] -> connecting +0ms
ioredis:cluster getting slot cache from 127.0.0.1:6420 +2ms
ioredis:redis queue command[0] -> cluster(slots) +2ms
ioredis:redis queue command[0] -> cluster(info) +2ms
ioredis:redis status[127.0.0.1:6400]: connecting -> connect +6ms
ioredis:redis write command[0] -> info() +1ms
ioredis:redis status[127.0.0.1:6410]: connecting -> connect +2ms
ioredis:redis write command[0] -> info() +0ms
ioredis:redis status[127.0.0.1:6420]: connecting -> connect +0ms
ioredis:redis write command[0] -> info() +0ms
ioredis:redis status[127.0.0.1:6410]: connect -> ready +14ms
ioredis:connection send 1 commands in offline queue +0ms
ioredis:redis write command[0] -> cluster(info) +1ms
ioredis:redis status[127.0.0.1:6400]: connect -> ready +1ms
Redis Cluster Info="cluster_state:ok\r\ncluster_slots_assigned:16384\r\ncluster_slots_ok:16384\r\ncluster_slots_pfail:0\r\ncluster_slots_fail:0\r\ncluster_known_nodes:6\r\ncluster_size:3\r\ncluster_current_epoch:3\r\ncluster_my_epoch:2\r\ncluster_stats_messages_ping_sent:7405\r\ncluster_stats_messages_pong_sent:6762\r\ncluster_stats_messages_meet_sent:1\r\ncluster_stats_messages_sent:14168\r\ncluster_stats_messages_ping_received:6758\r\ncluster_stats_messages_pong_received:7406\r\ncluster_stats_messages_meet_received:4\r\ncluster_stats_messages_received:14168\r\n"
ioredis:redis status[127.0.0.1:6420]: connect -> ready +2ms
ioredis:connection send 1 commands in offline queue +1ms
ioredis:redis write command[0] -> cluster(slots) +0ms
ioredis:redis status[127.0.0.1:6401]: [empty] -> connecting +11ms
ioredis:redis status[127.0.0.1:6421]: [empty] -> connecting +1ms
ioredis:redis status[127.0.0.1:6411]: [empty] -> connecting +0ms
ioredis:cluster status: connecting -> connect +1ms
ioredis:redis write command[0] -> cluster(info) +1ms
ioredis:redis status[127.0.0.1:6401]: connecting -> connect +3ms
ioredis:redis write command[0] -> info() +1ms
ioredis:redis status[127.0.0.1:6421]: connecting -> connect +1ms
ioredis:redis write command[0] -> info() +1ms
ioredis:redis status[127.0.0.1:6411]: connecting -> connect +0ms
ioredis:redis write command[0] -> info() +0ms
ioredis:cluster status: connect -> ready +1ms
Redis Cluster is Ready.
ioredis:redis status[127.0.0.1:6411]: connect -> ready +5ms
ioredis:connection set the connection to readonly mode +0ms
ioredis:redis write command[0] -> readonly() +1ms
ioredis:redis status[127.0.0.1:6401]: connect -> ready +2ms
ioredis:connection set the connection to readonly mode +2ms
ioredis:redis write command[0] -> readonly() +0ms
ioredis:redis status[127.0.0.1:6421]: connect -> ready +1ms
ioredis:connection set the connection to readonly mode +1ms
ioredis:redis write command[0] -> readonly() +0ms
^C
About this issue
- Original URL
- State: closed
- Created 6 years ago
- Comments: 20
Again, thanks for digging into this. I have some rather ugly code that periodically performs a CLUSTER NODES and compares the count with cluster.nodes and if the count is different I destroy and recreate the ioredis client. Not the cleanest or more efficient. Similarly, to work around the issue captured here where the client never connects - I simply have a timeout to guard against this condition and again destroy and recreate the ioredis client. Looking forward to ripping that code out and completely rely on ioredis to maintain and automatically recover connections.