A very fast retry strategy hangs blocking commands forever

[manast]

I was debugging an issue reported to BullMQ related to reconnections and I found something really strange that somehow seems to also affect blocking connections (need to investigate this more though).

How to reproduce

Run this simple code:

const Redis = require("ioredis");

const connection = new Redis({
  maxRetriesPerRequest: null,
  retryStrategy: function (times) {
    return 10;
  },
});
connection.on("connect", async () => {
    console.log("Connected to Redis!")
    const result = await connection.set("test", "test");   
    console.log("OK, Command issued", result);
});
connection.on("error", (err) => console.error("Redis error", err.message));
connection.on("reconnecting", () => console.log("Reconnecting to Redis!"));

You will get this output:

Connected to Redis!
OK, Command issued OK

Leave the code running and just close your Redis instance, in my case since I am running docker:

docker stop some-redis

Wait a few seconds and then start it again:

docker start some-redis

The result would be:

Redis error connect ECONNREFUSED 127.0.0.1:6379
Reconnecting to Redis!
Redis error connect ECONNREFUSED 127.0.0.1:6379
Reconnecting to Redis!
Redis error connect ECONNREFUSED 127.0.0.1:6379
Reconnecting to Redis!
Connected to Redis!
Reconnecting to Redis!
Connected to Redis!
OK, Command issued OK
OK, Command issued OK
OK, Command issued OK
OK, Command issued OK

Notice that the output of 4 "OK, Command issued OK". Somehow the callback to the connect event was called 4 times instead of one. Now if we modify the code to retry once per second instead:

const Redis = require("ioredis");

const connection = new Redis({
  maxRetriesPerRequest: null,
  retryStrategy: function (times) {
    return 1000;
  },
});
connection.on("connect", async () => {
    console.log("Connected to Redis!")
    const result = await connection.set("test", "test");   
    console.log("OK, Command issued", result);
});
connection.on("error", (err) => console.error("Redis error", err.message));
connection.on("reconnecting", () => console.log("Reconnecting to Redis!"));

And we do the same as we did above then we get the correct output, i.e. one single output of "OK, Command issued OK".

It seems like there is a small hazard that happens when the retries happen very close together. Not sure if this is completely harmless or not, since I am not done debugging my particular case, but I think this should be investigated and resolved if possible.

[manast]

My suspictions turned out to be correct. If you have issued a blocking command, then for some reason it gets stuck in that command ONLY when the retry is very fast. So adding this code to the original issue:

async function run() {
  while (true) {
    console.log("Waiting for message...");
    const result = await connection.brpop("whatever", 1);
    console.log("Message received", result);
  }
}

run();

It will try to do a blocking pop with a 1-second timeout. While it is connected it will loop forever with 1-second timeout. If you stop Redis and you have a very fast retry delay, and then start redis again it will not continue looping anymore...

[manast]

@luin it would be great if you could peek at this issue, it seems like it is snowballing 🤔 anything I can do to help?

[luin]

@manast 👋

I was not able to reproduce the issue:

CleanShot.2023-02-11.at.15.48.56.mp4

No matter if I changed retryStrategy to 10 or 1, I always got one "Command issued". Do I miss anything?

[manast]

Is the Redis instance running locally or inside a docker container? (in my case I run it in a docker container, but the test itself in my local machine).

[manast]

Also, did you try replacing the set command by brpop as in the second comment?

[luin]

Thanks! I finally reproduced this with docker. This happens when reconnecting successfully but the ready check fails. In our code, what we do at different events:

1. On close, we move the unfulfilled commands from commandQueue to prevCommandQueue.
2. On connect, we reset commandQueue.
3. On ready, we resent commands in prevCommandQueue.

When the issue happens, the events are emitted in the order close -> connect -> close -> connect -> ready, so brpop is lost at the second close.

[manast]

Yes, that makes a lot of sense. I have had similar issues in the past as it is difficult to guarantee the order of asynchronous events that happens very tight and that can potentially interleave.

[github-actions]

🎉 This issue has been resolved in version 5.3.1 🎉

The release is available on:

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

Your semantic-release bot 📦🚀