Redis [BUG] Cluster replica(s) dead loop on "Failed trying to load the MASTER synchronization DB from disk"

9:C 19 Oct 2021 01:12:31.412 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

9:C 19 Oct 2021 01:12:31.412 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=9, just started

#### cleaned ####

Comment From: pnthai88

On the master node

9:C 19 Oct 2021 01:18:28.813 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

9:C 19 Oct 2021 01:18:28.813 # Redis version=6.2.6, bits=64, commit=00000000, modified=0, pid=9, just started

#### cleaned ####

Comment From: oranagra

@pnthai88 i don't see any other errors in the log, so i wanna get a better understanding of the reproduction scenario. is there any data in the cluster? or is it just an empty cluster with a module and a replica failing to sync? does this issue also happen if you remove the module from the equation?

Comment From: pnthai88

@oranagra : it's not working on data exist or empty or no module loaded or module loaded

If without swapdb parameter.

It's keep failing sync, i raised client-output-buffer-limit.... already

Comment From: oranagra

i'm suspecting it's related to the module. i don't know much about it, but i suppose that if you'll show that without the module it stops failing, then you should report this issue for the module developers to debug.

Comment From: pnthai88

Yea,

But if i remove the module and run cluster without "swapdb" mode, it still failing sync on slaves too.

If you want to have a look, i'm willing let you access team viewer to discover it :)

Comment From: pnthai88

@oranagra , I just try out and it's now working on the replica nodes, i replaced folder mapping with volume in docker

# this will not work . Causing dead loop sync error, unable load from disk
volumes:
   - ./LOCAL_TEST_SERVER_DATA/RedisCluster/volume/vol-redis-replica-3-data:/data

with this one will working:

# this will working, no more dead loop
volumes:
   - vol-redis-replica-3-data:/data

volume define:

volumes:
  vol-redis-replica-0-data:
  vol-redis-replica-1-data:
  vol-redis-replica-2-data:
  vol-redis-replica-3-data:
  vol-redis-replica-4-data:

I think the problem is at mapping folder will not work on replication.

Now i'm able to run the cluster without "swapdb" mode

Comment From: oranagra

ok, now i realize that this could be a simple case of not being able to open the file for reading. apparently when that happens we don't print the problem and errno to the log (i'll fix it).

anyway, so this means the problem was the docker configuration (not really a bug in redis). so we can close this issue, right?

Comment From: pnthai88

@oranagra No, i think it's a bug... may be.

Because in docker the master node can read and write to RDB.

But the replica not. It need volume defined.

I also tried save "" to prevent rdb writing and it's not working too. You may have a look at it

Comment From: oranagra

@pnthai88 can you try to apply this patch then and re-test (so we can see which error it is):

--- a/src/replication.c
+++ b/src/replication.c
@@ -1859,7 +1859,7 @@ void readSyncBulkPayload(connection *conn) {
         if (rdbLoad(server.rdb_filename,&rsi,RDBFLAGS_REPLICATION) != C_OK) {
             serverLog(LL_WARNING,
                 "Failed trying to load the MASTER synchronization "
-                "DB from disk");
+                "DB from disk: %s", strerror(errno));
             cancelReplicationHandshake(1);
             if (server.rdb_del_sync_files && allPersistenceDisabled()) {
                 serverLog(LL_NOTICE,"Removing the RDB file obtained from "

or alternatively just edit rdbLoad and add some log prints into it to see if fopen fails or does it come from inside rdbLoadRio..

Comment From: oranagra

btw, IIUC you're using --repl-diskless-sync yes, so the master isn't using the disk either.

Comment From: pnthai88

@oranagra with your incredible of works, i can't refuse it! I will try it in next 3 hours, i'm outside for work. Will let you know asap

Comment From: pnthai88

@oranagra here you are: Failed trying to load the MASTER synchronization DB from disk: No such file or directory

 19 Oct 2021 12:42:31.368 * MASTER <-> REPLICA sync: Flushing old data

9:S 19 Oct 2021 12:42:31.368 * MASTER <-> REPLICA sync: Loading DB in memory

9:S 19 Oct 2021 12:42:31.371 # Failed trying to load the MASTER synchronization DB from disk: No such file or directory

9:S 19 Oct 2021 12:42:31.372 * Reconnecting to MASTER 172.0.0.100:6380 after failure

9:S 19 Oct 2021 12:42:31.372 * MASTER <-> REPLICA sync started

9:S 19 Oct 2021 12:42:31.372 * Non blocking connect for SYNC fired the event.

9:S 19 Oct 2021 12:42:31.372 * Master replied to PING, replication can continue...

The data name is o.r and it's exist

let me know, if you need more test.

Comment From: oranagra

@pnthai88 thanks.. that's very odd. first because the code in readSyncBulkPayload did rename the temp rdb file to that name successfully just a few lines above the call to rdbLoad which fails. and also because you show that the file exists. can you please add some log prints in rdbLoad before / after fopen, and maybe also clear errno errno=0; before fopen, so that we can be sure this error indeed comes from fopen, and not from somewhere inside rdbLoadRio

@yossigo can you think of any docker specific issue that can cause such a thing? i.e. file is writable, but when opening for read we get EEXIST?

Comment From: pnthai88

@oranagra can you send me debug code and correct where you want these logs?

Comment From: oranagra

please use this:

diff --git a/src/rdb.c b/src/rdb.c
index 3a1eeb915..23908e507 100644
--- a/src/rdb.c
+++ b/src/rdb.c
@@ -2754,11 +2754,16 @@ int rdbLoad(char *filename, rdbSaveInfo *rsi, int rdbflags) {
     FILE *fp;
     rio rdb;
     int retval;
-
-    if ((fp = fopen(filename,"r")) == NULL) return C_ERR;
+    errno = 0;
+    if ((fp = fopen(filename,"r")) == NULL) {
+        serverLog(LL_WARNING, "rdbLoad failed opening %s, %s", filename, strerror(errno));
+        return C_ERR;
+    }
     startLoadingFile(fp, filename,rdbflags);
     rioInitWithFile(&rdb,fp);
     retval = rdbLoadRio(&rdb,rdbflags,rsi);
+    if (retval==C_ERR)
+        serverLog(LL_WARNING, "rdbLoadRio failed, %s", strerror(errno));
     fclose(fp);
     stopLoading(retval==C_OK);
     return retval;

Comment From: pnthai88

@oranagra :

here you are:

10:S 20 Oct 2021 00:51:53.730 * Reconnecting to MASTER 172.0.0.11:6379 after failure
10:S 20 Oct 2021 00:51:53.730 * MASTER <-> REPLICA sync started
10:S 20 Oct 2021 00:51:53.730 * Non blocking connect for SYNC fired the event.
10:S 20 Oct 2021 00:51:53.730 * Master replied to PING, replication can continue...
10:S 20 Oct 2021 00:51:53.730 * Partial resynchronization not possible (no cached master)
10:S 20 Oct 2021 00:51:58.734 * Full resync from master: 8d841222160b2e86e05ca7b9d56d526d13314575:42
10:S 20 Oct 2021 00:51:58.736 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk
10:S 20 Oct 2021 00:51:58.737 * MASTER <-> REPLICA sync: Flushing old data
10:S 20 Oct 2021 00:51:58.737 * MASTER <-> REPLICA sync: Loading DB in memory
10:S 20 Oct 2021 00:51:58.740 # **before fopen filename: o.r | log: Resource temporarily unavailable**
10:S 20 Oct 2021 00:51:58.741 # **rdbLoad failed opening o.r, No such file or directory**
10:S 20 Oct 2021 00:51:58.741 # Failed trying to load the MASTER synchronization DB from disk: No such file or directory

Comment From: yossigo

@oranagra This is definitely something funny related to docker. @pnthai88 If I understand correctly, this works when you're mapping your directory to a volume and doesn't work when you do a simple bindmount - is that correct?

Comment From: pnthai88

@oranagra This is definitely something funny related to docker.

@pnthai88 If I understand correctly, this works when you're mapping your directory to a volume and doesn't work when you do a simple bindmount - is that correct?

Yea, that's correct. This bug is insane 😂

Comment From: yossigo

@pnthai88 In that case, I'd look for obvious things like permissions bits on the folder, different UIDs, etc. Or just workaround and use volumes if that works for you. Anyway - we can conclude this is not something we have to fix in Redis.

Comment From: pnthai88

@pnthai88 In that case, I'd look for obvious things like permissions bits on the folder, different UIDs, etc. Or just workaround and use volumes if that works for you. Anyway - we can conclude this is not something we have to fix in Redis.

Yea, i'm using volume for local development. This kind of error should be notice in https://redis.com/blog/top-redis-headaches-for-devops-replication-timeouts/

Comment From: pnthai88

@yossigo , @oranagra i just found the problem ! i'm making wordpress commerce site for my wife today for our small fun business. It's seriously slow , 20 seconds to load simple single page. At first i tried with folder mapping (slow) then i switch to volume mapping (very fast like usual) i think the problem is at Docker. When the cluster replicas write to a very very very slow folder mapping, so it raise error could not find the "rdb.dump" file. I think that's the core problem.

Comment From: yossigo

@pnthai88 Thanks for the update, closing this.