Snapchat
Multi-master replication timeout multiple times when one instance restarted
Configuration: Four multimaster in full mesh in ports 8881, 8882, 8883 and 8884 in same test machine --active-replica yes --multi-master yes --repl-diskless-sync yes --repl-timeout 180 In conf file the following config set to tolerate additional changed during the replication client-output-buffer-limit "normal 0 0 0 slave 0 0 0 pubsub 33554432 8388608 60"
Write 300k keys each 5KB, with 5min TTL. Once 300k keys written stop write because replication fails also without traffic. Stop one node 1 with control^C and restart (8881). Started node initial replication from 3 other master, due restart partial sync is not possible and full synchronization to be done with all node.
Current behavior: Only one replication succeed (from 8883), two other (8882 and 8884) eventually timeout after 3min, then full sync initiated again and only (8882) of the two succeed, after 3 min timeout the last one start and succeed (8884). Only after 3 full synchronization round the master_link_status:up and master_sync_in_progress:0. In test TTL was 5min which means that DB was empty in the middle of the test. Log indicated that all three master succeed transfering RDB to started node (8881), but when first RDB was restarted the node 1 forgot proceed with two other RDB / send REPLCONF ACK to two other host which probably trigger timeout.
Now restarting one instance takes 10min or longer, not sure if succeed at all with traffic. Changing repl-timeout to 60 make timeout shorter but might be issue when DB size grow, I assume.
Expected behavior: It should be possible to replicate data from all three master at the same time or query them one at the time instead of querying all and discarding. With Ring config each node would be connected to two node, but I expect second RDB sync fails and retry is needed
Truncated logs below:
Node 2/8882: first synch timeout, second succeed 331:335:S 05 Apr 2020 19:19:13.201 * Background RDB transfer terminated with success 331:335:S 05 Apr 2020 19:19:13.201 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 331:335:S 05 Apr 2020 19:19:13.201 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming
331:335:S 05 Apr 2020 19:22:14.825 # Connection with replica 127.0.0.1:8881 lost. 331:335:S 05 Apr 2020 19:22:15.004 * Replica 127.0.0.1:8881 asks for synchronization 331:335:S 05 Apr 2020 19:22:15.005 * Full resync requested by replica 127.0.0.1:8881 331:335:S 05 Apr 2020 19:22:15.008 * Delay next BGSAVE for diskless SYNC 331:335:S 05 Apr 2020 19:22:20.707 * Starting BGSAVE for SYNC with target: replicas sockets 331:335:S 05 Apr 2020 19:22:20.799 * Background RDB transfer started by pid 362 331:335:S 05 Apr 2020 19:22:38.641 * Background RDB transfer terminated with success 331:335:S 05 Apr 2020 19:22:38.642 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 331:335:S 05 Apr 2020 19:22:38.642 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 331:335:S 05 Apr 2020 19:22:41.692 * Synchronization with replica 127.0.0.1:8881 succeeded
Node 3/8883: first sync succeed 336:340:S 05 Apr 2020 19:18:38.143 * Background RDB transfer started by pid 360 336:340:S 05 Apr 2020 19:19:13.223 * Background RDB transfer terminated with success 336:340:S 05 Apr 2020 19:19:13.223 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 336:340:S 05 Apr 2020 19:19:13.223 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 336:340:S 05 Apr 2020 19:19:18.369 * Synchronization with replica 127.0.0.1:8881 succeeded
Node 4/8884: two first sync timeout 343:347:S 05 Apr 2020 19:18:37.707 * Background RDB transfer started by pid 358 343:347:S 05 Apr 2020 19:19:13.285 * Background RDB transfer terminated with success 343:347:S 05 Apr 2020 19:19:13.285 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 343:347:S 05 Apr 2020 19:19:13.285 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming
343:347:S 05 Apr 2020 19:22:14.312 # Disconnecting timedout replica: 127.0.0.1:8881 343:347:S 05 Apr 2020 19:22:14.312 # Connection with replica 127.0.0.1:8881 lost. 343:347:S 05 Apr 2020 19:22:15.005 * Replica 127.0.0.1:8881 asks for synchronization 343:347:S 05 Apr 2020 19:22:15.005 * Full resync requested by replica 127.0.0.1:8881 343:347:S 05 Apr 2020 19:22:15.008 * Delay next BGSAVE for diskless SYNC 343:347:S 05 Apr 2020 19:22:20.411 * Starting BGSAVE for SYNC with target: replicas sockets 343:347:S 05 Apr 2020 19:22:20.504 * Background RDB transfer started by pid 361 343:347:S 05 Apr 2020 19:22:44.830 * Background RDB transfer terminated with success 343:347:S 05 Apr 2020 19:22:44.831 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 343:347:S 05 Apr 2020 19:22:44.831 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming
343:347:S 05 Apr 2020 19:25:45.229 # Disconnecting timedout replica: 127.0.0.1:8881 343:347:S 05 Apr 2020 19:25:45.230 # Connection with replica 127.0.0.1:8881 lost. 343:347:S 05 Apr 2020 19:25:45.299 * Replica 127.0.0.1:8881 asks for synchronization 343:347:S 05 Apr 2020 19:25:45.299 * Full resync requested by replica 127.0.0.1:8881 343:347:S 05 Apr 2020 19:25:45.300 * Delay next BGSAVE for diskless SYNC 343:347:S 05 Apr 2020 19:25:51.271 * Starting BGSAVE for SYNC with target: replicas sockets 343:347:S 05 Apr 2020 19:25:51.331 * Background RDB transfer started by pid 363 343:347:S 05 Apr 2020 19:25:51.431 * Background RDB transfer terminated with success 343:347:S 05 Apr 2020 19:25:51.432 # Slave 127.0.0.1:8881 correctly received the streamed RDB file. 343:347:S 05 Apr 2020 19:25:51.432 * Streamed RDB transfer with replica 127.0.0.1:8881 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 343:347:S 05 Apr 2020 19:25:52.337 * Synchronization with replica 127.0.0.1:8881 succeeded
Node 1: - the one which was restarted 352:356:S 05 Apr 2020 19:18:31.339 * Connecting to MASTER 127.0.0.1:8882 352:356:S 05 Apr 2020 19:18:31.340 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:18:31.340 * Connecting to MASTER 127.0.0.1:8883 352:356:S 05 Apr 2020 19:18:31.341 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:18:31.341 * Connecting to MASTER 127.0.0.1:8884 352:356:S 05 Apr 2020 19:18:31.342 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:18:31.342 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:18:31.343 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:18:31.343 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:18:31.344 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:18:31.344 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:18:31.345 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:18:31.346 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:18:31.347 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:18:31.347 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:18:31.555 * Replica 127.0.0.1:8884 asks for synchronization 352:356:S 05 Apr 2020 19:18:31.556 * Full resync requested by replica 127.0.0.1:8884 352:356:S 05 Apr 2020 19:18:31.556 * Delay next BGSAVE for diskless SYNC 352:356:S 05 Apr 2020 19:18:31.848 * Replica 127.0.0.1:8882 asks for synchronization 352:356:S 05 Apr 2020 19:18:31.849 * Full resync requested by replica 127.0.0.1:8882 352:356:S 05 Apr 2020 19:18:31.849 * Delay next BGSAVE for diskless SYNC 352:356:S 05 Apr 2020 19:18:31.958 * Replica 127.0.0.1:8883 asks for synchronization 352:356:S 05 Apr 2020 19:18:31.958 * Full resync requested by replica 127.0.0.1:8883 352:356:S 05 Apr 2020 19:18:31.959 * Delay next BGSAVE for diskless SYNC 352:356:S 05 Apr 2020 19:18:37.385 * Starting BGSAVE for SYNC with target: replicas sockets 352:356:S 05 Apr 2020 19:18:37.432 * Background RDB transfer started by pid 357 352:356:S 05 Apr 2020 19:18:37.533 * Background RDB transfer terminated with success 352:356:S 05 Apr 2020 19:18:37.533 # Slave 127.0.0.1:8884 correctly received the streamed RDB file. 352:356:S 05 Apr 2020 19:18:37.534 # Slave 127.0.0.1:8882 correctly received the streamed RDB file. 352:356:S 05 Apr 2020 19:18:37.534 # Slave 127.0.0.1:8883 correctly received the streamed RDB file. 352:356:S 05 Apr 2020 19:18:37.535 * Streamed RDB transfer with replica 127.0.0.1:8884 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 352:356:S 05 Apr 2020 19:18:37.535 * Streamed RDB transfer with replica 127.0.0.1:8882 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 352:356:S 05 Apr 2020 19:18:37.536 * Streamed RDB transfer with replica 127.0.0.1:8883 succeeded (socket). Waiting for REPLCONF ACK from replica to enable streaming 352:356:S 05 Apr 2020 19:18:37.597 * Full resync from master: 3537b60543b43654f6975c49e8587f329946f22d:1122271397 352:356:S 05 Apr 2020 19:18:37.708 * Synchronization with replica 127.0.0.1:8884 succeeded 352:356:S 05 Apr 2020 19:18:37.708 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:18:37.896 * Full resync from master: 0db28801de486b6c69cb07e61e75fb8c5ae01da8:1121269338 352:356:S 05 Apr 2020 19:18:37.896 * Discarding previously cached master state. 352:356:S 05 Apr 2020 19:18:37.999 * Full resync from master: 506ec59629465e40af24eb14a7a2287593722a66:1113722321 352:356:S 05 Apr 2020 19:18:38.022 * Synchronization with replica 127.0.0.1:8882 succeeded 352:356:S 05 Apr 2020 19:18:38.023 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:18:38.144 * Synchronization with replica 127.0.0.1:8883 succeeded 352:356:S 05 Apr 2020 19:18:38.145 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:19:13.239 * MASTER <-> REPLICA sync: Keeping old data 352:356:S 05 Apr 2020 19:19:13.239 * MASTER <-> REPLICA sync: Loading DB in memory 352:356:S 05 Apr 2020 19:19:13.241 * Loading RDB produced by version 5.3.3 352:356:S 05 Apr 2020 19:19:13.242 * RDB age 35 seconds 352:356:S 05 Apr 2020 19:19:13.242 * RDB memory usage when created 1134.68 Mb 352:356:S 05 Apr 2020 19:19:18.166 * MASTER <-> REPLICA sync: Finished with success
352:356:S 05 Apr 2020 19:22:14.313 # I/O error trying to sync with MASTER: connection lost 352:356:S 05 Apr 2020 19:22:14.823 # Timeout receiving bulk data from MASTER... If the problem persists try to set the 'repl-timeout' parameter in keydb.conf to a larger value. 352:356:S 05 Apr 2020 19:22:14.998 * Connecting to MASTER 127.0.0.1:8882 352:356:S 05 Apr 2020 19:22:14.999 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:22:14.999 * Connecting to MASTER 127.0.0.1:8884 352:356:S 05 Apr 2020 19:22:15.000 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:22:15.000 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:22:15.001 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:22:15.002 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:22:15.002 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:22:15.004 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:22:15.004 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:22:20.412 * Full resync from master: 3537b60543b43654f6975c49e8587f329946f22d:1122288265 352:356:S 05 Apr 2020 19:22:20.506 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:22:20.708 * Full resync from master: 0db28801de486b6c69cb07e61e75fb8c5ae01da8:1121286330 352:356:S 05 Apr 2020 19:22:20.801 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:22:38.591 * MASTER <-> REPLICA sync: Keeping old data 352:356:S 05 Apr 2020 19:22:38.592 * MASTER <-> REPLICA sync: Loading DB in memory 352:356:S 05 Apr 2020 19:22:38.593 * Loading RDB produced by version 5.3.3 352:356:S 05 Apr 2020 19:22:38.593 * RDB age 18 seconds 352:356:S 05 Apr 2020 19:22:38.594 * RDB memory usage when created 725.01 Mb 352:356:S 05 Apr 2020 19:22:40.973 * MASTER <-> REPLICA sync: Finished with success
352:356:S 05 Apr 2020 19:25:45.231 # I/O error trying to sync with MASTER: connection lost 352:356:S 05 Apr 2020 19:25:45.296 * Connecting to MASTER 127.0.0.1:8884 352:356:S 05 Apr 2020 19:25:45.296 * MASTER <-> REPLICA sync started 352:356:S 05 Apr 2020 19:25:45.297 * Non blocking connect for SYNC fired the event. 352:356:S 05 Apr 2020 19:25:45.298 * Master replied to PING, replication can continue... 352:356:S 05 Apr 2020 19:25:45.299 * Partial resynchronization not possible (no cached master) 352:356:S 05 Apr 2020 19:25:51.271 * Full resync from master: 3537b60543b43654f6975c49e8587f329946f22d:1122304012 352:356:S 05 Apr 2020 19:25:51.332 * MASTER <-> REPLICA sync: receiving streamed RDB from master 352:356:S 05 Apr 2020 19:25:51.333 * MASTER <-> REPLICA sync: Keeping old data 352:356:S 05 Apr 2020 19:25:51.333 * MASTER <-> REPLICA sync: Loading DB in memory 352:356:S 05 Apr 2020 19:25:51.335 * Loading RDB produced by version 5.3.3 352:356:S 05 Apr 2020 19:25:51.335 * RDB age 0 seconds 352:356:S 05 Apr 2020 19:25:51.336 * RDB memory usage when created 14.93 Mb 352:356:S 05 Apr 2020 19:25:51.338 * MASTER <-> REPLICA sync: Finished with success
I made some more tests
- with empty DB the master sync are done one by one and there is no timeout between. I suspect that ping between masters (repl-ping-replica-period 10) somehow fails when RDB sync takes more than x seconds
- I tested 4 multi master host with ring config (each had 2 replica), same problem timeout after first RDB sync timeouts so issue seems to be relevant when more 1 slave.
Mandating full sync with all replica after all partial sync failed does not sound right solution. Would it be possible to make RDB with one replica and then retry partial sync with remaining replica instead. Running N-1 full RDB when N multi-master might not work in real deployment because N-1 RDB might take too long time.
I've just opened PR #280 to address this. There are actually two bugs at play here, both causing timeouts on different nodes. This fix solves some of them. We'll continue to look into the other ones. Thanks for reporting.
