Connection hangs after temporarily lost connection from redis

[gpad]

Description

If I open a connection like this:

const conn = await createClient(options)
      .on("connect", () => {
        console.log("redis connect")
      })
      .on("ready", () => {
        console.log("redis ready")
      })
      .on("end", () => {
        console.log("redis end")
      })
      .on("error", async (error) => {
        console.log("redis error", error)
      })
      .on("reconnecting", () => {
        console.log("redis reconnecting")
      })
      .connect()

await conn.set('key', 'value');

I see this logs:

>> redis connect 
>> redis ready 

thank I can use the connection without any issue.

If I restart Redis to simulate a connection lost, I see an automatic reconnection with the following logs:

>> redis error SocketClosedUnexpectedlyError: Socket closed unexpectedly
>> redis reconnecting
>> redis connect

First of all, I never see ready and then if I try to use the connection await conn.set('key', 'value'); the call remain blocked indefinitely.

Node.js Version

v16.13.0 + v18.17.1

Redis Server Version

6.2.6

Node Redis Version

4.6.10

Platform

linux / docker

Logs

No response

[gguimond]

We experienced the same behavior, do you manage to find the issue or fix it ?

[gpad]

I have subscribed to the error event and when it's triggered I close the connection and reopen a new one ... It's not a perfect solution but it works in my scenario.

[leibale]

I tried reproducing it using the steps you described, but... its working as expected...
Are you running redis using a docker?

[gpad]

I tried reproducing it using the steps you described, but... its working as expected... Are you running redis using a docker?

Yes, and I have seen this behaviour also in PROD in a GKE

[leibale]

I am starting a docker using:

docker run -p 6379:6379 redis

then run this script:

import { createClient } from 'redis';

const client = await createClient()
  .on('error', (err) => console.error('client error', err))
  .on('connect', () => console.log('connect'))
  .on('ready', () => console.log('ready'))
  .connect();

setInterval(async () => {
  try {
    console.log(new Date().toJSON(), await client.ping());
  } catch (err) {
    console.error('command error', err);
  }
}, 1000);

when the server is up I see these logs:

connect
ready
2023-11-09T16:15:45.264Z PONG
2023-11-09T16:15:46.265Z PONG
2023-11-09T16:15:47.266Z PONG
2023-11-09T16:15:48.267Z PONG

then I take the docker down, I see this in the logs:

client error SocketClosedUnexpectedlyError: Socket closed unexpectedly
    at Socket.<anonymous> (/home/leibale/Workspace/test/node_modules/@redis/client/dist/lib/client/socket.js:194:118)
    at Object.onceWrapper (node:events:629:26)
    at Socket.emit (node:events:514:28)
    at TCP.<anonymous> (node:net:337:12)
client error Error: connect ECONNREFUSED 127.0.0.1:6379
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 6379
}
...

then when I restart the server it goes back to

connect
ready
2023-11-09T16:15:49.267Z PONG
2023-11-09T16:15:50.267Z PONG
2023-11-09T16:15:51.268Z PONG
2023-11-09T16:15:52.269Z PONG
2023-11-09T16:15:53.268Z PONG
2023-11-09T16:15:54.269Z PONG

am I missing something? are you doing things differently?

[gpad]

It's veri similar to mine, the only difference could be that I restart the docker with docker restart redis and I made await conn.set('key', 'value'); but the real difference is that I don't see the ready event.

Also @gguimond suffer by the same issue ...

I'm on linux I don't know if it's matter

[gpad]

this is my script:

import { createClient } from "redis"

async function main() {
  const conn = await createClient({ url: "redis://:redis@localhost:6379/1" })
    .on("connect", () => {
      console.log("redis connect")
    })
    .on("ready", () => {
      console.log("redis ready")
    })
    .on("end", () => {
      console.log("redis end")
    })
    .on("error", async (error) => {
      console.log("redis error", error)
    })
    .on("reconnecting", () => {
      console.log("redis reconnecting")
    })
    .connect()

  setInterval(async () => {
    console.log("set...")
    await conn.set("key", "value")
    console.log("get: ", await conn.get("key"))
  }, 1000)
}

main().then(console.log).catch(console.log)

and this is my docker-compose:

  ork-redis:
    image: redis:6.2.6-alpine
    container_name: redis
    command: redis-server --requirepass redis
    ports:
      - "6379:6379"
    volumes:
      - ork-redis-data:/data
    restart: unless-stopped
    environment:
      REDIS_PASSWORD: redis
      REDIS_REPLICATION_MODE: master

and then I restart with docker restart redis and I get:

$ node a.mjs 
redis connect
redis ready
undefined
set...
get:  value
set...
get:  value
set...
get:  value
set...
get:  value
set...
get:  value
set...
get:  value
set...
get:  value
redis error SocketClosedUnexpectedlyError: Socket closed unexpectedly
    at Socket.<anonymous> (/home/gpad/workspace/gpad/redis-bug/node_modules/@redis/client/dist/lib/client/socket.js:194:118)
    at Object.onceWrapper (node:events:510:26)
    at Socket.emit (node:events:390:28)
    at TCP.<anonymous> (node:net:687:12)
redis reconnecting
redis connect
set...
set...
set...
set...
set...
set...
set...

node version 16 & 18

$ node -v
v18.17.1

and

$ node -v
v18.17.1

$ node -v
v16.13.0

Let me know If I can help you in some way

[gguimond]

I'm able to reproduce with your script and docker-compose so I guess @leibale will be able also.
I've investigated the issue and have found that when redis server is shutting down, the client tries to reconnect right away by creating new socket but it seems that the socket can be created and connected without error at first, and so the client starts the "initiator" step and send AUTH command. (maybe the server still accepts connection because not complety shut down?)

What happens next is that the command is hanging out and the connection is never considered "ready" but no further reconnection is planned.
If we go into detail, the socket is closed but nothing happens because the on('close') callback does nothing when the connection is not ready. So, no error, no queue flushed etc.

I've made it working as expected by managing the case in socket close event callback, emitting an error if the connection is not ready. Hence, the pending AUTH command is flushed and the error is catched here

node-redis/packages/client/lib/client/socket.ts

Lines 164 to 173 in a8b81bd

	} catch (err) {
	const retryIn = this.#shouldReconnect(retries++, err as Error);
	if (typeof retryIn !== 'number') {
	throw retryIn;
	}
	this.emit('error', err);
	await promiseTimeout(retryIn);
	this.emit('reconnecting');
	}

. Then, the reconnection attempts are made and when redis server is up, the client is reconnected and further commands are fine.

node-redis/packages/client/lib/client/socket.ts

Lines 201 to 205 in a8b81bd

	.once('close', hadError => {
	if (!hadError && this.#isReady && this.#socket === socket) {
	this.#onSocketError(new SocketClosedUnexpectedlyError());
	}
	})

replaced by

.once('close', hadError => {
    if (!hadError && this.#socket === socket) {
        if(this.#isReady){
            this.#onSocketError(new SocketClosedUnexpectedlyError());
        } else {
            this.emit('error', new SocketClosedUnexpectedlyError())
        }
    }
})

The only dawback with this solution is that the error event is emitted 2 times, on one hand in the code added above and then in the catch in #connect(). I guess the maintainer will manage to a better solution but that's the idea.

[leibale]

@gguimond good job digging into it and finding the issue!
Wanna review #2653? 🙏
On top of that, I'm not sure how to add a test for this.. do you have any idea?

edit: BTW, I think that I wasn't able to reproduce the issue because i didn't have a password on my (local only) redis server, which means the "socket initiator" phase is noop..

[gguimond]

I tried to add a test besides this one https://github.com/redis/node-redis/blob/master/packages/client/lib/client/index.spec.ts#L715 with a new method testWithClientRestart which would restart docker just before launch the test function but unfortunately I don't manage to reproduce the issue in this context and even the current code is able to reconnect.
Regarding the PR, it seems fine to me (better than my proposal) but it still emits the error twice. I don't know if we can do better.

[leibale]

I think I'll merge and release it as is, we can make it better in next releases.. (2 error events shouldn't crash anyone)
Thanks for your help!

[gguimond]

Thank you, it is appreciated.