Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

multiple concurrent connect if error happened when connect #2320

Closed
F3n67u opened this issue Nov 6, 2022 · 6 comments
Closed

multiple concurrent connect if error happened when connect #2320

F3n67u opened this issue Nov 6, 2022 · 6 comments

Comments

@F3n67u
Copy link

F3n67u commented Nov 6, 2022

I created an Azure redis, it allows access only via SSL. I misconfigure my protocol to redis://(connect will trigger error) and found that:

  1. "Socket closed unexpectedly" error triggered multiple concurrent connect.
  2. there is a TypeError: Cannot read properties of undefined (reading 'destroy')

How to reproduce

  1. Create the following script:
const redis = require('redis');

const client = redis.createClient({
  url: 'redis://:lcUgWq70QiZDdPiWAz61Z2oIHQvAjWVChAzCaH7Qb90=@feng-test.redis.cache.windows.net:6380/0',
});
client.connect().then(() => console.log('connected'));

let reconnectCount = 0;
let lastConnect = Date.now();
client.on('reconnecting', () => {
  console.log(
    'reconnecting, count: ',
    ++reconnectCount,
    ' last connect is',
    lastConnect ? Date.now() - lastConnect : 'null',
    'ms ago',
  );
  lastConnect = Date.now();
});
client.on('error', (error) => {
  console.log('error: ', error.toString());
});
  1. run this script

Actual behavior

from the log, we can see that:

  1. there are more and more concurrent connect, the first time is 2 concurrent connect and then 3, 4, 5...
  2. there is a TypeError: Cannot read properties of undefined (reading 'destroy')
2022-11-06T03:02:36.015Z error:  Error: Socket closed unexpectedly
2022-11-06T03:02:36.018Z reconnecting, count:  1  last reconnect is null ms ago
2022-11-06T03:02:36.020Z error:  Error: Socket closed unexpectedly
2022-11-06T03:02:36.023Z reconnecting, count:  2  last reconnect is 5 ms ago
2022-11-06T03:02:57.448Z error:  Error: Socket closed unexpectedly
2022-11-06T03:02:57.448Z reconnecting, count:  3  last reconnect is 21425 ms ago
2022-11-06T03:02:57.451Z error:  Error: Socket closed unexpectedly
2022-11-06T03:02:57.452Z error:  TypeError: Cannot read properties of undefined (reading 'destroy')
2022-11-06T03:02:57.452Z reconnecting, count:  4  last reconnect is 3 ms ago
2022-11-06T03:02:57.502Z reconnecting, count:  5  last reconnect is 49 ms ago
2022-11-06T03:03:35.978Z error:  Error: Socket closed unexpectedly
2022-11-06T03:03:35.979Z reconnecting, count:  6  last reconnect is 38476 ms ago
2022-11-06T03:03:35.981Z error:  Error: Socket closed unexpectedly
2022-11-06T03:03:35.981Z error:  TypeError: Cannot read properties of undefined (reading 'destroy')
2022-11-06T03:03:35.982Z error:  TypeError: Cannot read properties of undefined (reading 'destroy')
2022-11-06T03:03:35.983Z reconnecting, count:  7  last reconnect is 3 ms ago
2022-11-06T03:03:36.034Z reconnecting, count:  8  last reconnect is 50 ms ago
2022-11-06T03:03:36.084Z reconnecting, count:  9  last reconnect is 49 ms ago

Expected behavior

  1. If error happened when connect, there should only trigger 1 reconnect, not multiple reconnect.
  2. there is no TypeError: Cannot read properties of undefined (reading 'destroy')

Environment:

  • Node.js Version: v18.2.0
  • Redis Server Version: 6
  • Node Redis Version: 4.1.1
  • Platform: Mac OS 13.0

My investigation

For now, I only investigated the multiple concurrent connect issue. I tried but didn't figure out why "Cannot read properties of undefined (reading 'destroy')" happen.

In RedisSocket.#connect(), when an error happened when connect:

  1. an error event is emitted, and the error event listener of RedisSocket(#onSocketError) invokes the RedisSocket.#conncect
  2. besides, because we use the default reconnect strategy, this error triggers another connect loop

So every time, RedisSocket.#conncect in #onSocketError creates 1 more new connect and concurrent connect become more and more.

this.emit('error', err);

#onSocketError(err: Error): void {
this.#isReady = false;
this.emit('error', err);
this.#connect(true).catch(() => {
// the error was already emitted, silently ignore it
});
}

I think we can skip RedisSocket.#conncect in #onSocketError if the socket is still in the connecting phase.

@F3n67u F3n67u added the Bug label Nov 6, 2022
@F3n67u F3n67u changed the title trigger multiple concurrent connect if "Socket closed unexpectedly" happened when connect multiple concurrent connect if error happened when connect Nov 6, 2022
@leibale
Copy link
Collaborator

leibale commented Nov 9, 2022

Can you please try to upgrade to 4.4.0?
edit: I've tried it with 4.4.0 and looks like it still not working as it should, I'll take a look tomorrow

Might be a duplicate of #2010

@leibale
Copy link
Collaborator

leibale commented Jan 24, 2023

Feel free to reopen if the issue still exists

@leibale leibale closed this as not planned Won't fix, can't repro, duplicate, stale Jan 24, 2023
@orinciog
Copy link

Hi!

I'm using the latest version of node-redis (4.6.4), and this bug is still present.

[2023-01-31T14:18:43.643Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.643Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.644Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.644Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.644Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.644Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.645Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2023-01-31T14:18:43.645Z] [ERROR]  error Cannot read properties of undefined (reading 'destroy') TypeError: Cannot read properties of undefined (reading 'destroy')
    at RedisSocket._RedisSocket_connect (/service/node_modules/@redis/client/dist/lib/client/socket.js:155:71)
    at runMicrotasks (<anonymous>)
        ....
[2023-01-31T14:18:43.752Z] [INFO]  reconnecting
[2023-01-31T14:18:43.799Z] [INFO]  reconnecting
[2023-01-31T14:18:43.801Z] [INFO]  reconnecting
[2023-01-31T14:18:43.801Z] [INFO]  reconnecting
[2023-01-31T14:18:43.850Z] [INFO]  reconnecting
[2023-01-31T14:18:43.851Z] [INFO]  reconnecting
[2023-01-31T14:18:43.851Z] [INFO]  reconnecting
[2023-01-31T14:18:43.900Z] [INFO]  reconnecting
[2023-01-31T14:18:43.943Z] [INFO]  reconnecting
[2023-01-31T14:18:43.943Z] [INFO]  reconnecting
[2023-01-31T14:18:43.952Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.156Z] [INFO]  reconnecting
[2023-01-31T14:18:44.339Z] [INFO]  reconnecting
[2023-01-31T14:18:44.339Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.340Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting
[2023-01-31T14:18:44.343Z] [INFO]  reconnecting

The code is very simple and is similar to @F3n67u .
[ERROR] error is from client.on('error')
[INFO] reconnecting is from client.on('reconnecting')

The flow is:

  • start redis
  • start client
  • restart redis
  • in client appears a lot of reconnect messages

@leibale
Copy link
Collaborator

leibale commented Jan 31, 2023

@orinciog can you please share your code so I'll be able to reproduce the issue?

@orinciog
Copy link

orinciog commented Feb 1, 2023

@leibale Thank you for you very quick answer. I was using a simple code, just like the above code. Testing it on different scenarios to show you, I realized that the problems were introduced by the istio sidecar proxy.

The only scenario in which I had problems which reconnection was when I deployed redis client in kubernetes with istio sidecar proxy in front of client. With istio, the client had a lot of reconnection problems:

  • multiple "Socket closed unexpectedly" errors
  • multiple TypeError: Cannot read properties of undefined (reading 'destroy')
  • multiple and quick reconnect events
  • unable to reconnect after "LOADING Redis is loading the dataset in memory" error

After I disabled the istio sidecar, everything was ok, so the problem is on istio proxy side.

Thank you again for your quick answer.

@mstrofbass
Copy link

You can reproduce the issue by...and don't ask me how I know this...pointing Redis at a RabbitMQ server. Obviously the underlying cause is the connection being broken but I don't think the library should enter an infinite reconnect loop when this occurs.

Example with docker compose:

version: "3.9"
services:

  rabbitmq:
    image: rabbitmq:3-management-alpine
    ports:
      - 5672:5672
      - 15672:15672
import { createClient } from "redis";

async function run() {
  const url = "redis://guest:guest@localhost:5672"
  const client = createClient({ url });
  client.on("error", () => { console.error("Redis Client Error"); });
  client.connect();
}

run();

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants