KeyDB
KeyDB copied to clipboard
Snapchat
[BUG] Stuck at 100% CPU usage with diskless sync multimaster cluster
Describe the bug
KeyDB hangs with 100% CPU usage when using multimaster clusters with diskless replication.
To reproduce
base.conf:
protected-mode no
tcp-backlog 511
timeout 600
tcp-keepalive 300
supervised no
loglevel notice
databases 16
always-show-logo yes
lazyfree-lazy-eviction no
lazyfree-lazy-expire no
lazyfree-lazy-server-del no
replica-lazy-flush no
lua-time-limit 5000
slowlog-log-slower-than 10000
slowlog-max-len 128
latency-monitor-threshold 0
notify-keyspace-events ""
hash-max-ziplist-entries 512
hash-max-ziplist-value 64
list-max-ziplist-size -2
list-compress-depth 0
set-max-intset-entries 512
zset-max-ziplist-entries 128
zset-max-ziplist-value 64
hll-sparse-max-bytes 3000
stream-node-max-bytes 4096
stream-node-max-entries 100
activerehashing yes
client-output-buffer-limit normal 0 0 0
client-output-buffer-limit replica 0 0 0
client-output-buffer-limit pubsub 32mb 8mb 60
hz 10
dynamic-hz yes
repl-diskless-sync yes
repl-diskless-sync-delay 5
repl-disable-tcp-nodelay no
save ""
appendonly no
server-threads 8
maxclients 100000
maxmemory 2Gb
maxmemory-policy noeviction
replica-serve-stale-data yes
replica-read-only no
active-replica yes
multi-master yes
1.conf:
include ./base.conf
port 6379
replicaof 127.0.0.1 6380
replicaof 127.0.0.1 6381
pidfile ./data1/1.pid
dir ./data1
2.conf:
include ./base.conf
port 6380
replicaof 127.0.0.1 6379
replicaof 127.0.0.1 6381
pidfile ./data2/2.pid
dir ./data2
3.conf:
include ./base.conf
port 6381
replicaof 127.0.0.1 6379
replicaof 127.0.0.1 6380
pidfile ./data3/3.pid
dir ./data3
run.sh:
#!/bin/bash
killall -9 keydb-server
rm -rf data{1..3}
mkdir data{1..3}
{ ./keydb-server ./1.conf | sed 's/^/A: /g;s/$/ (A)/g'; } &
sleep 1
{ ./keydb-server ./2.conf | sed 's/^/B: /g;s/$/ (B)/g'; } &
sleep 1
{ ./keydb-server ./3.conf | sed 's/^/C: /g;s/$/ (C)/g'; } &
k() {
echo
echo "Killing keydb NOW!"
killall -9 keydb-server
echo
}
trap k SIGINT
wait
Expected behavior
No hanging processes with 100% CPU usage.
Additional information
This issue does not occur with a high LA (iff NOTICE: Detuning locks due to high load per core can be seen in the logs directly at startup, the issue does not occur in my tests).
Given the above, I assume the problem is caused by the assembly fastlock implementation.
Logs:
[daniil@daniil-arch keydb-test]$ ./run.sh
keydb-server: no process found
A: 43531:43531:C 11 Nov 2022 14:07:12.786 * Before turning into a replica, using my own master parameters to synthesize a cached master: I may be able to synchronize with the new master with just a partial transfer. (A)
A: 43531:43531:C 11 Nov 2022 14:07:12.786 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo (A)
A: 43531:43531:C 11 Nov 2022 14:07:12.786 # KeyDB version=255.255.255, bits=64, commit=e8a85cf5, modified=0, pid=43531, just started (A)
A: 43531:43531:C 11 Nov 2022 14:07:12.786 # Configuration loaded (A)
A: 43531:43531:C 11 Nov 2022 14:07:12.786 # WARNING: server-threads is greater than this machine's core count. Truncating to 4 threads (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 # You requested maxclients of 100000 requiring at least 100032 max file descriptors. (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 # Server can't set maximum open files to 100032 because of OS error: Operation not permitted. (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 # Current maximum open files is 10000. maxclients has been reduced to 9968 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'. (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 * monotonic clock: POSIX clock_gettime (A)
A: (A)
A: _ (A)
A: _-(+)-_ (A)
A: _-- / \ --_ (A)
A: _-- / \ --_ KeyDB 255.255.255 (e8a85cf5/0) 64 bit (A)
A: __-- / \ --__ (A)
A: (+) _ / \ _ (+) Running in standalone mode (A)
A: | -- / \ -- | Port: 6379 (A)
A: | /--_ _ _--\ | PID: 43531 (A)
A: | / -(+)- \ | (A)
A: | / | \ | https://docs.keydb.dev (A)
A: | / | \ | (A)
A: | / | \ | (A)
A: (+)_ -- -- -- | -- -- -- _(+) (A)
A: --_ | _-- (A)
A: --_ | _-- (A)
A: -(+)- KeyDB has now joined Snap! See the announcement at: https://docs.keydb.dev/news (A)
A: (A)
A: (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 # Server initialized (A)
A: 43531:43531:S 11 Nov 2022 14:07:12.791 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect. (A)
A: 43531:43545:S 11 Nov 2022 14:07:12.792 * Thread 0 alive. (A)
A: 43531:43546:S 11 Nov 2022 14:07:12.792 * Thread 1 alive. (A)
A: 43531:43547:S 11 Nov 2022 14:07:12.792 * Thread 2 alive. (A)
A: 43531:43545:S 11 Nov 2022 14:07:12.792 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43548:S 11 Nov 2022 14:07:12.792 * Thread 3 alive. (A)
A: 43531:43545:S 11 Nov 2022 14:07:12.792 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:07:12.792 # Error condition on socket for SYNC: Connection refused (A)
B: 43553:43553:C 11 Nov 2022 14:07:13.787 * Before turning into a replica, using my own master parameters to synthesize a cached master: I may be able to synchronize with the new master with just a partial transfer. (B)
B: 43553:43553:C 11 Nov 2022 14:07:13.787 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo (B)
B: 43553:43553:C 11 Nov 2022 14:07:13.787 # KeyDB version=255.255.255, bits=64, commit=e8a85cf5, modified=0, pid=43553, just started (B)
B: 43553:43553:C 11 Nov 2022 14:07:13.787 # Configuration loaded (B)
B: 43553:43553:C 11 Nov 2022 14:07:13.787 # WARNING: server-threads is greater than this machine's core count. Truncating to 4 threads (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.792 # You requested maxclients of 100000 requiring at least 100032 max file descriptors. (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.792 # Server can't set maximum open files to 100032 because of OS error: Operation not permitted. (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.792 # Current maximum open files is 10000. maxclients has been reduced to 9968 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'. (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.792 * monotonic clock: POSIX clock_gettime (B)
B: (B)
B: _ (B)
B: _-(+)-_ (B)
B: _-- / \ --_ (B)
B: _-- / \ --_ KeyDB 255.255.255 (e8a85cf5/0) 64 bit (B)
B: __-- / \ --__ (B)
B: (+) _ / \ _ (+) Running in standalone mode (B)
B: | -- / \ -- | Port: 6380 (B)
B: | /--_ _ _--\ | PID: 43553 (B)
B: | / -(+)- \ | (B)
B: | / | \ | https://docs.keydb.dev (B)
B: | / | \ | (B)
B: | / | \ | (B)
B: (+)_ -- -- -- | -- -- -- _(+) (B)
B: --_ | _-- (B)
B: --_ | _-- (B)
B: -(+)- KeyDB has now joined Snap! See the announcement at: https://docs.keydb.dev/news (B)
B: (B)
B: (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.793 # Server initialized (B)
B: 43553:43553:S 11 Nov 2022 14:07:13.793 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect. (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.793 * Thread 0 alive. (B)
B: 43553:43567:S 11 Nov 2022 14:07:13.793 * Thread 1 alive. (B)
B: 43553:43569:S 11 Nov 2022 14:07:13.793 * Thread 2 alive. (B)
B: 43553:43570:S 11 Nov 2022 14:07:13.793 * Thread 3 alive. (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.794 * Connecting to MASTER 127.0.0.1:6379 (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.794 * MASTER <-> REPLICA sync started (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.795 * Non blocking connect for SYNC fired the event. (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.795 * Master replied to PING, replication can continue... (B)
B: 43553:43565:S 11 Nov 2022 14:07:13.795 * Trying a partial resynchronization (request a04d9d983f410dc5b4cac5b6c0433d62d867d612:1). (B)
A: 43531:43545:S 11 Nov 2022 14:07:13.795 * Replica 127.0.0.1:6380 asks for synchronization (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.795 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'a04d9d983f410dc5b4cac5b6c0433d62d867d612', my replication IDs are '44d4707516d478eff3b686fc33e4dc2426d2da59' and '0000000000000000000000000000000000000000') (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.795 * Replication backlog created, my new replication IDs are '1b8473b2a449f4d2216745b3d20bf8505aeb5dd4' and '0000000000000000000000000000000000000000' (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.795 * Delay next BGSAVE for diskless SYNC (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.799 * Connecting to MASTER 127.0.0.1:6381 (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.799 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:07:13.799 # Error condition on socket for SYNC: Connection refused (A)
C: 43574:43574:C 11 Nov 2022 14:07:14.789 * Before turning into a replica, using my own master parameters to synthesize a cached master: I may be able to synchronize with the new master with just a partial transfer. (C)
C: 43574:43574:C 11 Nov 2022 14:07:14.789 # oO0OoO0OoO0Oo KeyDB is starting oO0OoO0OoO0Oo (C)
C: 43574:43574:C 11 Nov 2022 14:07:14.789 # KeyDB version=255.255.255, bits=64, commit=e8a85cf5, modified=0, pid=43574, just started (C)
C: 43574:43574:C 11 Nov 2022 14:07:14.789 # Configuration loaded (C)
C: 43574:43574:C 11 Nov 2022 14:07:14.789 # WARNING: server-threads is greater than this machine's core count. Truncating to 4 threads (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.794 # You requested maxclients of 100000 requiring at least 100032 max file descriptors. (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.795 # Server can't set maximum open files to 100032 because of OS error: Operation not permitted. (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.795 # Current maximum open files is 10000. maxclients has been reduced to 9968 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'. (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.795 * monotonic clock: POSIX clock_gettime (C)
C: (C)
C: _ (C)
C: _-(+)-_ (C)
C: _-- / \ --_ (C)
C: _-- / \ --_ KeyDB 255.255.255 (e8a85cf5/0) 64 bit (C)
C: __-- / \ --__ (C)
C: (+) _ / \ _ (+) Running in standalone mode (C)
C: | -- / \ -- | Port: 6381 (C)
C: | /--_ _ _--\ | PID: 43574 (C)
C: | / -(+)- \ | (C)
C: | / | \ | https://docs.keydb.dev (C)
C: | / | \ | (C)
C: | / | \ | (C)
C: (+)_ -- -- -- | -- -- -- _(+) (C)
C: --_ | _-- (C)
C: --_ | _-- (C)
C: -(+)- KeyDB has now joined Snap! See the announcement at: https://docs.keydb.dev/news (C)
C: (C)
C: (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.795 # Server initialized (C)
C: 43574:43574:S 11 Nov 2022 14:07:14.795 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect. (C)
C: 43574:43587:S 11 Nov 2022 14:07:14.796 * Thread 1 alive. (C)
C: 43574:43586:S 11 Nov 2022 14:07:14.796 * Thread 0 alive. (C)
C: 43574:43589:S 11 Nov 2022 14:07:14.796 * Thread 2 alive. (C)
C: 43574:43591:S 11 Nov 2022 14:07:14.796 * Thread 3 alive. (C)
C: 43574:43586:S 11 Nov 2022 14:07:14.797 * Connecting to MASTER 127.0.0.1:6379 (C)
C: 43574:43586:S 11 Nov 2022 14:07:14.797 * MASTER <-> REPLICA sync started (C)
A: 43531:43545:S 11 Nov 2022 14:07:14.797 * Replica 127.0.0.1:6381 asks for synchronization (A)
C: 43574:43586:S 11 Nov 2022 14:07:14.797 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:07:14.797 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for 'a35011d095f780abf9791573f716e9cc0e214919', my replication IDs are '1b8473b2a449f4d2216745b3d20bf8505aeb5dd4' and '0000000000000000000000000000000000000000') (A)
C: 43574:43586:S 11 Nov 2022 14:07:14.797 * Master replied to PING, replication can continue... (C)
A: 43531:43545:S 11 Nov 2022 14:07:14.797 * Delay next BGSAVE for diskless SYNC (A)
C: 43574:43586:S 11 Nov 2022 14:07:14.797 * Trying a partial resynchronization (request a35011d095f780abf9791573f716e9cc0e214919:1). (C)
A: 43531:43545:S 11 Nov 2022 14:07:14.804 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:07:14.805 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:07:14.805 * Non blocking connect for SYNC fired the event. (A)
A: 43531:43545:S 11 Nov 2022 14:07:14.805 * Master replied to PING, replication can continue... (A)
A: 43531:43545:S 11 Nov 2022 14:07:14.806 * Trying a partial resynchronization (request 44d4707516d478eff3b686fc33e4dc2426d2da59:1). (A)
B: 43553:43565:S 11 Nov 2022 14:07:14.806 * Replica 127.0.0.1:6379 asks for synchronization (B)
B: 43553:43565:S 11 Nov 2022 14:07:14.806 * Partial resynchronization not accepted: Replication ID mismatch (Replica asked for '44d4707516d478eff3b686fc33e4dc2426d2da59', my replication IDs are 'a04d9d983f410dc5b4cac5b6c0433d62d867d612' and '0000000000000000000000000000000000000000') (B)
B: 43553:43565:S 11 Nov 2022 14:07:14.806 * Replication backlog created, my new replication IDs are '88ddd5867db1823399bcf9a2cd141b4ede9d3155' and '0000000000000000000000000000000000000000' (B)
B: 43553:43565:S 11 Nov 2022 14:07:14.806 * Delay next BGSAVE for diskless SYNC (B)
A: 43531:43545:S 11 Nov 2022 14:07:18.834 * Starting BGSAVE for SYNC with target: replicas sockets (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.835 * Background RDB transfer started (A)
B: 43553:43565:S 11 Nov 2022 14:07:18.837 * Full resync from master: 1b8473b2a449f4d2216745b3d20bf8505aeb5dd4:0 (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.837 * Discarding previously cached master state. (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.837 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk (B)
A: 43531:43593:S 11 Nov 2022 14:07:18.837 * RDB: 32 MB of memory used by copy-on-write (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.837 # Diskless rdb transfer, done reading from pipe, 2 replicas still up. (A)
B: 43553:43565:S 11 Nov 2022 14:07:18.837 * MASTER <-> REPLICA sync: Loading DB in memory (B)
C: 43574:43586:S 11 Nov 2022 14:07:18.837 * Full resync from master: 1b8473b2a449f4d2216745b3d20bf8505aeb5dd4:0 (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.837 * Discarding previously cached master state. (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.837 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.837 * MASTER <-> REPLICA sync: Loading DB in memory (C)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 * Loading RDB produced by version 255.255.255 (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 * RDB age 0 seconds (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 * RDB memory usage when created 29.85 Mb (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 # Done loading RDB, keys loaded: 0, keys expired: 0. (B)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 * RDB contains information on 0 masters (B)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 * Loading RDB produced by version 255.255.255 (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 * RDB age 0 seconds (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 * RDB memory usage when created 29.85 Mb (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 # Done loading RDB, keys loaded: 0, keys expired: 0. (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 * RDB contains information on 0 masters (C)
C: 43574:43586:S 11 Nov 2022 14:07:18.860 * MASTER <-> REPLICA sync: Finished with success (C)
B: 43553:43565:S 11 Nov 2022 14:07:18.860 * MASTER <-> REPLICA sync: Finished with success (B)
A: 43531:43545:S 11 Nov 2022 14:07:18.861 * Background RDB transfer terminated with success (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.861 * Streamed RDB transfer with replica 127.0.0.1:6380 succeeded (socket). Waiting for REPLCONF ACK from slave to enable streaming (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.861 * Streamed RDB transfer with replica 127.0.0.1:6381 succeeded (socket). Waiting for REPLCONF ACK from slave to enable streaming (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.861 * Synchronization with replica 127.0.0.1:6380 succeeded (A)
A: 43531:43545:S 11 Nov 2022 14:07:18.861 * Synchronization with replica 127.0.0.1:6381 succeeded (A)
C: 43574:43586:S 11 Nov 2022 14:07:19.841 * Connecting to MASTER 127.0.0.1:6380 (C)
B: 43553:43565:S 11 Nov 2022 14:07:19.841 * Connecting to MASTER 127.0.0.1:6381 (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.841 * MASTER <-> REPLICA sync started (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.841 * Starting BGSAVE for SYNC with target: replicas sockets (B)
A: 43531:43545:S 11 Nov 2022 14:07:19.842 * Full resync from master: 88ddd5867db1823399bcf9a2cd141b4ede9d3155:0 (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.842 * Discarding previously cached master state. (A)
B: 43553:43565:S 11 Nov 2022 14:07:19.842 * Background RDB transfer started (B)
C: 43574:43586:S 11 Nov 2022 14:07:19.842 * MASTER <-> REPLICA sync started (C)
B: 43553:43565:S 11 Nov 2022 14:07:19.842 * Non blocking connect for SYNC fired the event. (B)
C: 43574:43586:S 11 Nov 2022 14:07:19.842 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:07:19.843 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.843 * MASTER <-> REPLICA sync: Loading DB in memory (A)
B: 43553:43565:S 11 Nov 2022 14:07:19.843 * Master replied to PING, replication can continue... (B)
C: 43574:43586:S 11 Nov 2022 14:07:19.843 * Master replied to PING, replication can continue... (C)
B: 43553:43565:S 11 Nov 2022 14:07:19.843 * Partial resynchronization not possible (no cached master) (B)
C: 43574:43586:S 11 Nov 2022 14:07:19.843 * Partial resynchronization not possible (no cached master) (C)
C: 43574:43586:S 11 Nov 2022 14:07:19.843 * Replica 127.0.0.1:6380 asks for synchronization (C)
C: 43574:43586:S 11 Nov 2022 14:07:19.843 * Full resync requested by replica 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:07:19.843 * Delay next BGSAVE for diskless SYNC (C)
B: 43553:43565:S 11 Nov 2022 14:07:19.843 * Replica 127.0.0.1:6381 asks for synchronization (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.843 * Full resync requested by replica 127.0.0.1:6381 (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.843 * Current BGSAVE has socket target. Waiting for next BGSAVE for SYNC (B)
B: 43553:43610:S 11 Nov 2022 14:07:19.844 * RDB: 32 MB of memory used by copy-on-write (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.844 # Diskless rdb transfer, done reading from pipe, 1 replicas still up. (B)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 * Loading RDB produced by version 255.255.255 (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 * RDB age 0 seconds (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 * RDB memory usage when created 29.83 Mb (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 # Done loading RDB, keys loaded: 0, keys expired: 0. (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 * RDB contains information on 1 masters (A)
A: 43531:43545:S 11 Nov 2022 14:07:19.866 * MASTER <-> REPLICA sync: Finished with success (A)
B: 43553:43565:S 11 Nov 2022 14:07:19.866 * Background RDB transfer terminated with success (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.866 * Streamed RDB transfer with replica 127.0.0.1:6379 succeeded (socket). Waiting for REPLCONF ACK from slave to enable streaming (B)
B: 43553:43565:S 11 Nov 2022 14:07:19.866 * Synchronization with replica 127.0.0.1:6379 succeeded (B)
A: 43531:43545:S 11 Nov 2022 14:07:20.849 * Connecting to MASTER 127.0.0.1:6381 (A)
A: 43531:43545:S 11 Nov 2022 14:07:20.849 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:07:20.850 * Non blocking connect for SYNC fired the event. (A)
A: 43531:43545:S 11 Nov 2022 14:07:20.850 * Master replied to PING, replication can continue... (A)
A: 43531:43545:S 11 Nov 2022 14:07:20.850 * Partial resynchronization not possible (no cached master) (A)
C: 43574:43586:S 11 Nov 2022 14:07:20.850 * Replica 127.0.0.1:6379 asks for synchronization (C)
C: 43574:43586:S 11 Nov 2022 14:07:20.850 * Full resync requested by replica 127.0.0.1:6379 (C)
C: 43574:43586:S 11 Nov 2022 14:07:20.851 * Delay next BGSAVE for diskless SYNC (C)
B: 43553:43565:S 11 Nov 2022 14:07:24.893 * Starting BGSAVE for SYNC with target: replicas sockets (B)
C: 43574:43586:S 11 Nov 2022 14:07:24.893 * Starting BGSAVE for SYNC with target: replicas sockets (C)
A: 43531:43545:S 11 Nov 2022 14:07:24.893 * Full resync from master: a35011d095f780abf9791573f716e9cc0e214919:645 (A)
B: 43553:43565:S 11 Nov 2022 14:07:24.893 * Background RDB transfer started (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.893 * Full resync from master: a35011d095f780abf9791573f716e9cc0e214919:645 (B)
C: 43574:43586:S 11 Nov 2022 14:07:24.894 * Background RDB transfer started (C)
C: 43574:43586:S 11 Nov 2022 14:07:24.894 * Full resync from master: 88ddd5867db1823399bcf9a2cd141b4ede9d3155:329 (C)
A: 43531:43545:S 11 Nov 2022 14:07:24.895 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.895 * MASTER <-> REPLICA sync: Loading DB in memory (A)
B: 43553:43565:S 11 Nov 2022 14:07:24.896 * MASTER <-> REPLICA sync: receiving streamed RDB from master with EOF to disk (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.896 * MASTER <-> REPLICA sync: Loading DB in memory (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.896 * Replica is about to load the RDB file received from the master, but there is a pending RDB child running. Cancelling RDB the save and removing its temp file to avoid any race (B)
C: 43574:43618:S 11 Nov 2022 14:07:24.897 * RDB: 32 MB of memory used by copy-on-write (C)
C: 43574:43586:S 11 Nov 2022 14:07:24.897 # Diskless rdb transfer, done reading from pipe, 2 replicas still up. (C)
B: 43553:43617:S 11 Nov 2022 14:07:24.897 * RDB: 32 MB of memory used by copy-on-write (B)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 * Loading RDB produced by version 255.255.255 (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 * RDB age 0 seconds (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 * RDB memory usage when created 29.89 Mb (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 # Done loading RDB, keys loaded: 0, keys expired: 0. (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 * RDB contains information on 1 masters (A)
A: 43531:43545:S 11 Nov 2022 14:07:24.907 * MASTER <-> REPLICA sync: Finished with success (A)
C: 43574:43586:S 11 Nov 2022 14:07:24.907 * Background RDB transfer terminated with success (C)
C: 43574:43586:S 11 Nov 2022 14:07:24.907 * Streamed RDB transfer with replica 127.0.0.1:6380 succeeded (socket). Waiting for REPLCONF ACK from slave to enable streaming (C)
C: 43574:43586:S 11 Nov 2022 14:07:24.907 * Streamed RDB transfer with replica 127.0.0.1:6379 succeeded (socket). Waiting for REPLCONF ACK from slave to enable streaming (C)
C: 43574:43586:S 11 Nov 2022 14:07:24.907 * Synchronization with replica 127.0.0.1:6379 succeeded (C)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 * Loading RDB produced by version 255.255.255 (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 * RDB age 0 seconds (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 * RDB memory usage when created 29.89 Mb (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 # Done loading RDB, keys loaded: 0, keys expired: 0. (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 * RDB contains information on 1 masters (B)
B: 43553:43565:S 11 Nov 2022 14:07:24.908 * MASTER <-> REPLICA sync: Finished with success (B)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 # MASTER timeout: no data nor PING received... (A)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 # Connection with master lost. (A)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 * Caching the disconnected master state. (A)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:08:24.311 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:08:25.298 # Timeout receiving bulk data from MASTER... If the problem persists try to set the 'repl-timeout' parameter in keydb.conf to a larger value. (C)
C: 43574:43586:S 11 Nov 2022 14:08:25.298 # Disconnecting timedout replica (streaming sync): 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:08:25.298 # Connection with replica 127.0.0.1:6380 lost. (C)
A: 43531:43545:S 11 Nov 2022 14:08:25.315 # Disconnecting timedout replica (streaming sync): 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:08:25.315 # Connection with replica 127.0.0.1:6380 lost. (A)
C: 43574:43586:S 11 Nov 2022 14:08:26.302 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:08:26.303 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:08:26.303 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:09:25.771 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:09:26.779 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:09:26.779 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:09:26.779 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:09:27.765 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:09:28.773 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:09:28.773 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:09:28.773 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:10:27.210 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:10:28.217 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:10:28.218 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:10:28.218 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:10:29.200 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:10:30.206 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:10:30.206 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:10:30.206 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:11:29.690 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:11:30.700 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:11:30.700 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:11:30.701 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:11:31.708 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:11:32.718 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:11:32.718 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:11:32.718 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:12:31.208 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:12:32.218 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:12:32.218 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:12:32.218 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:12:33.227 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:12:34.236 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:12:34.236 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:12:34.237 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:13:33.721 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:13:34.729 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:13:34.729 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:13:34.730 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:13:35.737 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:13:36.746 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:13:36.746 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:13:36.746 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:14:35.190 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:14:36.199 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:14:36.200 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:14:36.200 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:14:37.207 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:14:38.219 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:14:38.219 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:14:38.219 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:15:37.648 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:15:38.654 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:15:38.655 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:15:38.655 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:15:39.697 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:15:40.704 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:15:40.704 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:15:40.704 * Non blocking connect for SYNC fired the event. (C)
A: 43531:43545:S 11 Nov 2022 14:16:39.075 # Timeout connecting to the MASTER... (A)
A: 43531:43545:S 11 Nov 2022 14:16:40.084 * Connecting to MASTER 127.0.0.1:6380 (A)
A: 43531:43545:S 11 Nov 2022 14:16:40.084 * MASTER <-> REPLICA sync started (A)
A: 43531:43545:S 11 Nov 2022 14:16:40.085 * Non blocking connect for SYNC fired the event. (A)
C: 43574:43586:S 11 Nov 2022 14:16:41.150 # Timeout connecting to the MASTER... (C)
C: 43574:43586:S 11 Nov 2022 14:16:42.157 * Connecting to MASTER 127.0.0.1:6380 (C)
C: 43574:43586:S 11 Nov 2022 14:16:42.157 * MASTER <-> REPLICA sync started (C)
C: 43574:43586:S 11 Nov 2022 14:16:42.158 * Non blocking connect for SYNC fired the event. (C)
