Error: connect ETIMEDOUT ----use bluebird

[fengyh13]

I use bluebird replace native promise, error happened!

ioredis:redis status[172.31.15.99:5818]: [empty] -> connecting +0ms
  ioredis:redis queue command[172.31.15.99:5818]: 2 -> set([ 'aaa', '1' ]) +5ms
  ioredis:connection error: Error: connect ETIMEDOUT +0ms
redisClient connect to db error: { Error: connect ETIMEDOUT
    at Socket.<anonymous> (/opt/project/umichat/umichat_manage/node_modules/[email protected]@ioredis/built/redis/index.js:282:31)
    at Object.onceWrapper (events.js:313:30)
    at emitNone (events.js:106:13)
    at Socket.emit (events.js:208:7)
    at Socket._onTimeout (net.js:422:8)
    at ontimeout (timers.js:498:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:290:5) errorno: 'ETIMEDOUT', code: 'ETIMEDOUT', syscall: 'connect' }
  ioredis:redis status[172.31.15.99:5818]: connecting -> close +10s
  ioredis:connection reconnect in 50ms +3ms
  ioredis:redis status[172.31.15.99:5818]: close -> reconnecting +1ms
  ioredis:redis status[172.31.15.99:5818]: reconnecting -> connecting +50ms

envriment:

node: v8.16.0
redis server: 5.0.5
ioredis: 4.14.1
bluebird: 3.5.5

my test code

const bluebird = require('bluebird');
global.Promise = bluebird;
const Redis = require('ioredis');

const instance = new Redis({
  port: 6379,
  host: 'localhost',
  db: 2,
});

instance.on('error', e => {
  console.error(`redisClient connect to db error:`, e);
});

instance.set("aaa", 1)

[peterhanneman]

node: v12.11.1
redis: 5.0.5
ioredis: 4.14.1
bluebird: 3.7.0

Seeing the same issue as well. It only impacts the initial startup connection. Easiest workaround I've found is to set a low connectTimeout value. The subsequent retry works as expected. On a handful of occasions it has started properly the first time perhaps suggesting a race condition?

[comtaler]

The same happened to me on cluster mode with the following code:

const Redis = require('ioredis');
global.Promise = require('bluebird');
new Redis.Cluster( [{host: '127.0.0.1', port: 30001}]);

And here is the debug log:

ioredis:cluster status: [empty] -> connecting +0ms
ioredis:cluster:connectionPool Reset with [ { host: '127.0.0.1', port: 30001 } ] +0ms
ioredis:cluster:connectionPool Connecting to 127.0.0.1:30001 as master +3ms
ioredis:redis status[127.0.0.1:30001]: [empty] -> wait +0ms
ioredis:cluster getting slot cache from 127.0.0.1:30001 +8ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: [empty] -> wait +1ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: wait -> connecting +2ms
ioredis:redis queue command[127.0.0.1:30001 (ioredisClusterRefresher)]: 0 -> cluster([ 'slots' ]) +0ms
ioredis:cluster:subscriber selected a subscriber 127.0.0.1:30001 +0ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: [empty] -> wait +1ms
ioredis:cluster:subscriber started +1ms
[ioredis] Unhandled error event: ClusterAllFailedError: Failed to refresh slots cache.
at tryNode (/home/daniel-liang/code/popcorn/switchboard/src/njslib/node_modules/ioredis/built/cluster/index.js:359:31)
at /home/daniel-liang/code/popcorn/switchboard/src/njslib/node_modules/ioredis/built/cluster/index.js:376:21
at Timeout.duplicatedConnection.cluster.utils_2.timeout (/home/daniel-liang/code/popcorn/switchboard/src/njslib/node_modules/ioredis/built/cluster/index.js:623:24)
at Timeout.run (/home/daniel-liang/code/popcorn/switchboard/src/njslib/node_modules/ioredis/built/utils/index.js:156:22)
at ontimeout (timers.js:438:13)
at tryOnTimeout (timers.js:300:5)
at listOnTimeout (timers.js:263:5)
at Timer.processTimers (timers.js:223:10)
ioredis:cluster:connectionPool Reset with [] +1s
ioredis:cluster:connectionPool Disconnect 127.0.0.1:30001 because the node does not hold any slot +0ms
ioredis:redis status[127.0.0.1:30001]: wait -> close +1s
ioredis:connection skip reconnecting since the connection is manually closed. +0ms
ioredis:redis status[127.0.0.1:30001]: close -> end +1ms
ioredis:cluster:connectionPool Remove 127.0.0.1:30001 from the pool +1ms
ioredis:cluster:subscriber subscriber has left, selecting a new one... +1s
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: wait -> close +0ms
ioredis:connection skip reconnecting since the connection is manually closed. +1ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: close -> end +0ms
ioredis:cluster:subscriber selecting subscriber failed since there is no node discovered in the cluster yet +0ms
ioredis:cluster status: connecting -> close +1s
ioredis:cluster status: close -> reconnecting +1ms
ioredis:cluster connecting failed: Error: None of startup nodes is available +0ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: connecting -> close +2ms
ioredis:connection skip reconnecting since the connection is manually closed. +2ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: close -> end +0ms
ioredis:cluster Cluster is disconnected. Retrying after 102ms +102ms
ioredis:cluster status: reconnecting -> connecting +0ms
ioredis:cluster:connectionPool Reset with [ { host: '127.0.0.1', port: 30001 } ] +104ms
ioredis:cluster:connectionPool Connecting to 127.0.0.1:30001 as master +0ms
ioredis:redis status[127.0.0.1:30001]: [empty] -> wait +102ms
ioredis:cluster:subscriber a new node is discovered and there is no subscriber, selecting a new one... +104ms
ioredis:cluster:subscriber selected a subscriber 127.0.0.1:30001 +0ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: [empty] -> wait +0ms
ioredis:cluster getting slot cache from 127.0.0.1:30001 +1ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: [empty] -> wait +1ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterRefresher)]: wait -> connecting +0ms
ioredis:redis queue command[127.0.0.1:30001 (ioredisClusterRefresher)]: 0 -> cluster([ 'slots' ]) +0ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: wait -> close +0ms
ioredis:connection skip reconnecting since the connection is manually closed. +103ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: close -> end +0ms
ioredis:cluster:subscriber selected a subscriber 127.0.0.1:30001 +1ms
ioredis:redis status[127.0.0.1:30001 (ioredisClusterSubscriber)]: [empty] -> wait +0ms
ioredis:cluster:subscriber started +0ms

[vylan]

+1

[ohroy]

+10086
the current newest 4.14.1

[Noly1990]

check the file in node_modules /ioredis/built/connectors/StandaloneConnector.js
line 41, this promise is use native promise
if you replace the native promise of global or window with bluebird, will cause the ETIMEDOUT problem, but i don't why the bluebird will cause this problem
I just use native promise here, also if you set promise container of ioredis, it isn't work.
you should add

var Promise = PromiseContainer.get();

before return new Promise();

[tuananh]

i use the code OP posted above and don't have any problem.

DEBUG=* node redis.js
  ioredis:redis status[localhost:6379]: [empty] -> connecting +0ms
  ioredis:redis queue command[localhost:6379]: 2 -> set([ 'aaa', '1' ]) +3ms
  ioredis:redis status[127.0.0.1:6379]: connecting -> connect +8ms
  ioredis:redis write command[127.0.0.1:6379]: 2 -> select([ '2' ]) +1ms
  ioredis:redis write command[127.0.0.1:6379]: 2 -> info([]) +1ms
  ioredis:redis status[127.0.0.1:6379]: connect -> ready +4ms
  ioredis:connection send 1 commands in offline queue +0ms
  ioredis:redis write command[127.0.0.1:6379]: 2 -> set([ 'aaa', '1' ]) +0ms

[bendytree]

Just to echo what @Noly1990 said - looks like an issue with the assumption that global.Promise is native. See: https://github.com/luin/ioredis/blob/master/lib/connectors/StandaloneConnector.ts#L61

The root cause here is over my head, but a quick patch along these lines this would be an enormous help to our team:

return new (global._Promise || global.Promise)<NetStream>((resolve, reject) => {

[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.

[jehy]

Still actual: #1074

[lenovouser]

Experiencing this too :/

[alavers]

Bluebird is somehow too fast. It's changing the ordering of the event loop such that the connect event is firing before the connect handler gets a chance attach to it.

Here's a repro that demonstrates the problem:

global.Promise = require("bluebird");
const { createConnection } = require("net");

function test(host) {
  const start = process.hrtime();
  const p = new Promise(resolve => {
    const stream = createConnection({ port: 6379, host });
    console.log(host, process.hrtime(start));
    resolve(stream);
  }).then(stream => {
    stream.on("connect", () => console.log("connect", host, process.hrtime(start)));
  });
}

test('localhost');
test('127.0.0.1');

I think the reason localhost works is because it's being resolved, which adds enough delay to subvert bluebird's speed.

$ node test.js
localhost [ 0, 3945841 ]
127.0.0.1 [ 0, 72298 ]
connect localhost [ 0, 11466923 ]

We probably shouldn't be waiting for the connect() promise to resolve before attaching those event listeners to the stream. The fix might be simple. We could just pass in those event listeners as args to AbstractConnector.connect and attach them inside each connector implementation.

We should reopen this one @luin and can probably close #1074 as a dupe.

[luin]

I come to think of there's a todo for this issue: https://github.com/luin/ioredis/blob/758b3f29036c7830e963ac3d34d3ce9cc7c4cb52/lib/connectors/StandaloneConnector.ts#L54-L60

Currently the recommended way to plug custom Promise implementation would be using Redis.Promise = require('bluebird') (see https://github.com/luin/ioredis#plugging-in-your-own-promises-library), but indeed it doesn't work if the global Promise is switched to bluebird.

[alavers]

Hmm I see. This probably wasn't an issue before this change, when connections were converted from callbacks to promises: https://github.com/luin/ioredis/pull/906/files#diff-05873f3a84814480fe7e81d9cb56acf4R20

Is it simpler to just revert to callbacks? 🙃 it would be breaking @imatlopez 's custom connector contract...

[alavers]

Confirmed with a quick test that reverting to callbacks would resolve this issue, but with the caveat mentioned above.

As an alternative option, I naively tried following the comment advice do not connect before resolved like this:

diff --git a/lib/connectors/StandaloneConnector.ts b/lib/connectors/StandaloneConnector.ts
index 6285b64..8979746 100644
--- a/lib/connectors/StandaloneConnector.ts
+++ b/lib/connectors/StandaloneConnector.ts
@@ -1,4 +1,4 @@
-import { createConnection, TcpNetConnectOpts, IpcNetConnectOpts } from "net";
+import { createConnection, TcpNetConnectOpts, IpcNetConnectOpts, Socket } from "net";
 import { connect as createTLSConnection, SecureContextOptions } from "tls";
 import { CONNECTION_CLOSED_ERROR_MSG } from "../utils";
 import AbstractConnector, { ErrorEmitter } from "./AbstractConnector";
@@ -69,7 +69,7 @@ export default class StandaloneConnector extends AbstractConnector {
           if (options.tls) {
             this.stream = createTLSConnection(connectionOptions);
           } else {
-            this.stream = createConnection(connectionOptions);
+            this.stream = new Socket();
           }
         } catch (err) {
           reject(err);
@@ -77,6 +77,7 @@ export default class StandaloneConnector extends AbstractConnector {
         }
 
         resolve(this.stream);
+        this.stream.connect(connectionOptions);
       });
     });
   }

But it doesn't resolve the issue. For this alternative approach to work we'd probably have to move that stream.connect() call into redis/index.ts, but SentinelConnector would have to return connection options which again breaks @imatlopez 's custom connector contract.

What do you think @luin ?

[imatlopez]

you can tell whether a function wants a callback by the length of that function, no need to break the promise contract now

[luin]

@alavers I'd think we can check if stream has already connected before attaching the listener to connect event (https://github.com/luin/ioredis/blob/master/lib/redis/index.ts#L307) so can be:

if (isConnected(stream)) {
  process.nextTick(eventHandler.connectHandler(_this))
} else {
  stream.once(CONNECT_EVENT, eventHandler.connectHandler(_this));
}

Not sure if Node.js provides enough APIs for the isConnected method.

[bvallelunga]

Seeing the same issue here as well.

[ioredis-robot]

🎉 This issue has been resolved in version 4.16.2 🎉

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot 📦🚀

[ohroy]

nice ！