故障分析 | redis cluster 從庫無法自動恢復同步案例一則

背景

線上有一套6節點 redis cluster ，6分片 * 2副本，每個節點上2個例項，埠號分別為7000和7001。

診斷

登入該節點，檢視 redis 的日誌

22996:S 20 Jan 2023 07:27:15.091 * Connecting to MASTER x.x.x.46:7001
22996:S 20 Jan 2023 07:27:15.091 * MASTER <‐> REPLICA sync started
22996:S 20 Jan 2023 07:27:15.106 * Non blocking connect for SYNC fired the event.
22996:S 20 Jan 2023 07:27:15.106 * Master replied to PING, replication can continue...
22996:S 20 Jan 2023 07:27:15.106 * Trying a partial resynchronization (request 174e5c92c731090d3c9a05f6364ffff5a70e61d9:7180528579709).
22996:S 20 Jan 2023 07:35:29.263 * Full resync from master: 174e5c92c731090d3c9a05f6364ffff5a70e61d9:7180734380451
22996:S 20 Jan 2023 07:35:29.263 * Discarding previously cached master state.
22996:S 20 Jan 2023 07:44:47.717 * MASTER <‐> REPLICA sync: receiving 22930214160 bytes from master

例項啟動後和主庫進行連線，先嚐試 partial resync 失敗，後進行 full resync

22996:S 20 Jan 2023 07:48:07.305 * MASTER <‐> REPLICA sync: Flushing old data
22996:S 20 Jan 2023 07:53:24.576 * MASTER <‐> REPLICA sync: Loading DB in memory
22996:S 20 Jan 2023 07:59:59.491 * MASTER <‐> REPLICA sync: Finished with success

耗時11分鐘完成舊資料清理和新 rdb 載入，此時卻發現和主庫的連線中斷

22996:S 20 Jan 2023 07:59:59.521 # Connection with master lost.
22996:S 20 Jan 2023 07:59:59.521 * Caching the disconnected master state.

於是乎又發起和主庫的連線

22996:S 20 Jan 2023 08:00:00.404 * Connecting to MASTER x.x.x.46:7001
22996:S 20 Jan 2023 08:00:00.404 * MASTER <‐> REPLICA sync started
22996:S 20 Jan 2023 08:00:00.405 * Non blocking connect for SYNC fired the event.
22996:S 20 Jan 2023 08:00:00.406 * Master replied to PING, replication can continue...
22996:S 20 Jan 2023 08:00:00.408 * Trying a partial resynchronization (request 174e5c92c731090d3c9a05f6364ffff5a70e61d9:7180736029100).
22996:S 20 Jan 2023 08:08:21.849 * Full resync from master: 174e5c92c731090d3c9a05f6364ffff5a70e61d9:7180922115631

有2個疑問：

檢視主庫日誌，每9分鐘發起1次 bgsave ，每次 bgsave 期間新產生的記憶體有2600M之多，repl-backlog-size 預設只有100M，而從庫節點從當機到完成啟動耗時大約15分鐘，此時緩衝區中的複製位點早被覆蓋，難怪 partial resync 會失敗。

38241:C 20 Jan 2023 07:35:25.836 * DB saved on disk
38241:C 20 Jan 2023 07:35:26.552 * RDB: 2663 MB of memory used by copy‐on‐write
40362:M 20 Jan 2023 07:35:27.950 * Background saving terminated with success
40362:M 20 Jan 2023 07:35:27.950 * Starting BGSAVE for SYNC with target:disk
40362:M 20 Jan 2023 07:35:29.263 * Background saving started by pid 11680
11680:C 20 Jan 2023 07:44:44.585 * DB saved on disk
11680:C 20 Jan 2023 07:44:45.811 * RDB: 2681 MB of memory used by copy‐on‐write

繼續看日誌，

40362:M 20 Jan 2023 07:48:03.104 * Synchronization with replica x.x.x.45:7000 succeeded
40362:M 20 Jan 2023 07:48:17.100 * FAIL message received from 8e2a54fbaac768a5cc0e717f4aa93c6be8683ffe about ccb7589e3240bc95557ffb282435afd5dc13e4c9
40362:M 20 Jan 2023 07:50:17.109 # Disconnecting timedout replica:x.x.x.45:7000
40362:M 20 Jan 2023 07:50:17.109 # Connection with replica x.x.x.45:7000 lost.
40362:M 20 Jan 2023 07:53:26.114 * Clear FAIL state for node ccb7589e3240bc95557ffb282435afd5dc13e4c9: replica is reachable again.
40362:M 20 Jan 2023 08:00:00.408 * Replica x.x.x.45:7000 asks for sync hronization

解決方案