ioredis fails to connect to cluster

[jcstanaway]

Using Redis 4.0.8 & ioredis 3.2.2. I am standing up a Redis Cluster with 3 shards & 2 nodes per shard. In my environment, the Redis Nodes and the Redis Client start asynchronously. When the client attempts to connect to the nodes in the cluster, not all of the nodes have yet been started and the nodes haven't actually yet formed the cluster (i.e., redis-trib.rb hasn't yet been executed). When this happens, ioredis never appears to recover and never connects to the cluster even after the cluster has been formed. If I restart the client (after the cluster has been formed), then the client successfully connects to the cluster. Forcing the client to wait until after the cluster has been formed would be kludgey.

Part of the problem appears to be that the 'delay' value reported in the 'reconnecting' event is undefined and therefore ioredis never attempts to reconnect.

Additionally, the following non-default options are specified:

function _retryStrategy(times) {
    let retry;

    if (times === 1) {
        retry = 1;  // immediate retry
    } else {
        retry = Math.min((times - 1) * 2000, 20000);
    }
    logger.debug('_retryStrategy: times=%d, retry=%d', times, retry);
    return retry;
}

const options = {
    // Cluster-level options
    // Override ioredis defaults.
    clusterRetryStrategy   : _retryStrategy,
    enableOfflineQueue     : false,                     // ioredis default is true
    scaleReads             : 'all',                     // ioredis default is 'master'

    // Per Server options
    redisOptions: {
        // Override ioredis defaults.
        connectTimeout               : 2000,            // ioredis default is 10000
        autoResendUnfulfilledCommands: false,           // ioredis default is true
        retryStrategy                : _retryStrategy,
        readOnly                     : true            // ioredis default is false
    }
}

Below are the logs from the client:

{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"Connecting Redis 'CacheManager' client to Redis cache 'collections'.","time":"2018-02-13T15:26:50.964Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Using startupNode 127.0.0.1:6400.","time":"2018-02-13T15:26:50.965Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Using startupNode 127.0.0.1:6410.","time":"2018-02-13T15:26:50.965Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Using startupNode 127.0.0.1:6420.","time":"2018-02-13T15:26:50.965Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/app/collections-cache.js[M]","level":30,"msg":"------RedisDB connection initialized-----","time":"2018-02-13T15:26:50.993Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/app/collections-cache.js[M]","level":30,"msg":"Performing initial bulk load of Redis","time":"2018-02-13T15:26:51.094Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:26:51.095Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"connect event received from ioredis.","time":"2018-02-13T15:26:51.669Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Redis 'CacheManager' client is connected to Redis cache 'collections'.","time":"2018-02-13T15:26:51.669Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"_retryStrategy: times=1, retry=1","time":"2018-02-13T15:26:51.697Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"close event received from ioredis.","time":"2018-02-13T15:26:51.697Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":40,"msg":"Redis 'CacheManager' client connection to Redis cache 'collections' was closed. Waiting for auto-reconnect to occur.","time":"2018-02-13T15:26:51.698Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"reconnecting event received from ioredis. delay=NaN","time":"2018-02-13T15:26:51.698Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Redis 'CacheManager' client will attempt to reconnect to Redis cache 'collections' in undefined milliseconds.","time":"2018-02-13T15:26:51.698Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"connect event received from ioredis.","time":"2018-02-13T15:26:51.739Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Redis 'CacheManager' client is connected to Redis cache 'collections'.","time":"2018-02-13T15:26:51.740Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"close event received from ioredis.","time":"2018-02-13T15:26:51.747Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":40,"msg":"Redis 'CacheManager' client connection to Redis cache 'collections' was closed. Waiting for auto-reconnect to occur.","time":"2018-02-13T15:26:51.747Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"_retryStrategy: times=2, retry=2000","time":"2018-02-13T15:26:51.748Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":20,"msg":"reconnecting event received from ioredis. delay=NaN","time":"2018-02-13T15:26:51.748Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/redisdb/client.js[M]","level":30,"msg":"Redis 'CacheManager' client will attempt to reconnect to Redis cache 'collections' in undefined milliseconds.","time":"2018-02-13T15:26:51.748Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:01.098Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:11.104Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:21.111Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:31.113Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:41.120Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:27:51.121Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:01.123Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:11.132Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:21.144Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:31.146Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:41.148Z","v":0}
{"name":"collections-cache-518","hostname":"collections-cache-606766-z6c16","pid":1,"fileName":"/database/bulk-loader.js[M]","level":50,"msg":"Redis collections cache is not ready. Will retry bulk loading in 10 seconds...","time":"2018-02-13T15:28:51.150Z","v":0}
[...]

A ready event is never received.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 7 days if no further activity occurs, but feel free to re-open a closed issue if needed.

[jcstanaway]

Ping. It would be good to fix this issue. I've written some rather kludgy code in my client to periodically (~3 seconds) check if connected and if not destroy that ioredis Cluster instance and create a new one, but it isn't the cleanest solution at all. The library really needs to handle this scenario.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 7 days if no further activity occurs, but feel free to re-open a closed issue if needed.

[jcstanaway]

Commenting to keep this issue open.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 7 days if no further activity occurs, but feel free to re-open a closed issue if needed.

[jcstanaway]

@luin Any chance this will be addressed?

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 7 days if no further activity occurs, but feel free to re-open a closed issue if needed.

[jcstanaway]

unstale

[jeremytm]

@ccs018 you say you are using ioredis 3.2.2? Have you tried any newer versions of ioredis just to see if it's already fixed?

[jcstanaway]

Unfortunately, no. The project I was on that was using Redis Clusters was cancelled in August. I did scan through the changelog and there appeared to have been a number of interesting updates, but I am not able to verify if these resolve the original issue.

Before the project was cancelled I had a work-around that would timeout and kill the ioredis instance if no connections were made and then create a new instance. It was klugey, but it worked.

I don't know if you want to leave this open and attempt to reproduce the issue or if you'd just like to close it. Given the number of changes in ioredis 4.x and since my project was cancelled, I have no objections if you close it.