client.isReady returns true even when it's not actually ready

[hosein]

Description

Since there has been some behavioral change that I have not seen mention anywhere, I have been trying to find a good way to handle LOADING Redis is loading the dataset in memory errors when restarting from a large rdb file. Something that apparently was handled differently in past releases (either Redis or npm redis).

One of the methods I had intended to use is the client.isReady.

Unfortunately it seems to return true even when redis is still not quite ready.

Replication steps:
Fill a redis server with junk data, enough for it to take a few seconds to load from disk.
Write a script that connects to it and once the client.isReady returns true, attempt a PING command.

You'll find that it still fails to LOADING Redis is loading the dataset in memory

Node.js Version

16.20.2

Redis Server Version

7.2.3

Node Redis Version

4.6.8

Platform

No response

Logs

No response

[leibale]

isReady will be true as long as the socket is "alive", which is true even if the server is in "loading mode".
How do you expect the client to handle it?

[hosein]

Being alive (or responding to pings) is wholly different from being ready. I expect that when it says it is ready, then it is ready for commands. The ability to determine it is alive is available from the PING command. isReady implies more than just alive.

[Davrosh]

@leibale

As far as I understand checking to see if data has finished loading from the disk is the behavior using ioredis with enableReadyCheck set to true https://github.com/redis/ioredis?tab=readme-ov-file#connection-events . While it does seem from the docs that that is only the case when using clusters, it's still not obvious how to mitigate such LOADING errors in node-redis (now that ioredis is apparently deprecated #2658 (comment) ).

https://github.com/redis/node-redis/blob/master/CHANGELOG.md#v055---february-16-2011
Looking at the changelog, apparently the behavior has for a long time been to call the INFO command to check if the server is ready.
The question is whether or not it checks the INFO command for loading:0 to see if loading has finished and whether or not that happens on reconnect.

The scenario to reproduce:
Simulate loading heavy data to the redis-stack server on localhost and then try retrieving it in a loop.
If we kill the redis-stack server with CTRL-C and bring it back up, it seems that even though it's apparently ready it's still erroring just after its reconnection, right until data has finished loading.

What is the recommended way of handling such an error (also in production scenario you possibly access data from Redis through a dedicated handler)?

Run:

node loading.js

Code (loading.js):

const redis = require('redis');

const client = redis.createClient({
  url: 'redis://localhost:6379',
  socket: {
    reconnectStrategy: (retries) => {
      console.log(`Reconnect attempt #${retries}`);
      return Math.min(retries * 100, 3000);
    }
  }
});

client.on('error', (err) => console.log('Redis Client Error', err));
client.on('ready', () => console.log('Redis is ready'));
client.on('reconnecting', () => console.log('Redis is reconnecting'));

async function sleep(ms) {
    return new Promise(resolve => setTimeout(resolve, ms))
}

async function runTest() {

    await client.connect();

    for (let i = 0; i < 10000; i++) {
        await client.json.set(`key-${i}`, '$', {
            'a': i
        });
    }
  
    while (true) {
      const min = 0;
      const max = 9999;
      const randomNumber = Math.floor(Math.random() * (max - min + 1)) + min;
      try {
        console.log('trying to get', randomNumber);
        const value = await client.json.get(`key-${randomNumber}`);
        console.log('Operation successful. Retrieved value:', value);
      } catch (error) {
        console.error('Operation failed:', error.message);
      }
      await sleep(100);
    }
  }
  
  runTest().catch(console.error);

Tail of node loading.js logs (notice lines after Redis is reconnecting when redis gets back up):

Reconnect attempt #7
Redis Client Error Error: connect ECONNREFUSED 127.0.0.1:6379
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1187:16) {
  errno: -61,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 6379
}
Redis is reconnecting
Reconnect attempt #8
Redis Client Error Error: connect ECONNREFUSED 127.0.0.1:6379
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1187:16) {
  errno: -61,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 6379
}
Redis is reconnecting
Operation failed: LOADING Redis is loading the dataset in memory
Redis is ready
trying to get 792
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 7281
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 6336
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 6773
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 8269
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 7987
Operation failed: LOADING Redis is loading the dataset in memory
trying to get 466
Operation successful. Retrieved value: { a: 466 }
trying to get 9271
Operation successful. Retrieved value: { a: 9271 }

Tail of redis-stack-server logs (after reconnecting but loading takes 1.5s):

8945:M 04 Aug 2024 11:54:39.202 * Server initialized
98945:M 04 Aug 2024 11:54:39.202 * <search> Loading event starts
98945:M 04 Aug 2024 11:54:39.202 * <redisgears_2> Got a loading start event, clear the entire functions data.
98945:M 04 Aug 2024 11:54:39.202 * Loading RDB produced by version 7.2.4
98945:M 04 Aug 2024 11:54:39.202 * RDB age 4 seconds
98945:M 04 Aug 2024 11:54:39.202 * RDB memory usage when created 209.41 Mb
98945:M 04 Aug 2024 11:54:40.790 * Done loading RDB, keys loaded: 71300, keys expired: 0.
98945:M 04 Aug 2024 11:54:40.790 # <search> Skip background reindex scan, redis version contains loaded event.
98945:M 04 Aug 2024 11:54:40.790 * <search> Loading event ends
98945:M 04 Aug 2024 11:54:40.790 * <redisgears_2> Loading finished, re-enable key space notificaitons.
98945:M 04 Aug 2024 11:54:40.790 * DB loaded from disk: 1.588 seconds
98945:M 04 Aug 2024 11:54:40.790 * Ready to accept connections tcp

[DoobleD]

Looking for a solution to this as well!