1、 故障現象

某數據庫在2025-04-02發現備庫同步中斷,簡單查看數據庫LOG日誌中有如下的報錯信息:

2025-04-02 09:42:00.899 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:01.763 CST [2895266] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:03.773 CST [2895297] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:05.780 CST [2895370] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:05.903 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:07.786 CST [2895372] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:09.795 CST [2895438] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:10.906 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:11.803 CST [2895497] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:13.809 CST [2895567] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:15.818 CST [2895638] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:15.910 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:17.825 CST [2895689] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:19.831 CST [2895708] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:20.915 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:22.188 CST [2895730] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:24.194 CST [2895731] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:25.919 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法

2、 故障分析

2.1、 查詢failover工具日誌

查詢備庫的pg_auto_failover日誌信息,詳細信息如下:

2025-04-01 14:13:36.242576+08 |    0/2 |           secondary |          catchingup | Node node 2 "htzz_2" (192.168.111.12:1821) is marked as unhealthy by the monitor
 2025-04-01 14:31:42.846598+08 |    0/2 |          catchingup |          catchingup | New state is reported by node 2 "htzz_2" (192.168.111.12:1821): "catchingup"
 2025-04-01 14:31:44.043195+08 |    0/2 |          catchingup |          catchingup | Node node 2 "htzz_2" (192.168.111.12:1821) is marked as healthy by the monitor
 2025-04-01 14:31:44.071861+08 |    0/2 |          catchingup |           secondary | Setting goal state of node 2 "htzz_2" (192.168.111.12:1821) to secondary after it caught up.
 2025-04-01 15:06:55.821311+08 |    0/2 |          catchingup |          catchingup | Setting goal state of node 2 "htzz_2" (192.168.111.12:1821) to catchingup after it became unhealthy.
 2025-04-01 15:07:50.768441+08 |    0/2 |          catchingup |          catchingup | Node node 2 "htzz_2" (192.168.111.12:1821) is marked as unhealthy by the monitor

在14:08:51分中備庫的狀態從secondary轉到catchingup的狀態,表示備庫此時出現同步延遲的情況,在結合後面的不監控狀態,説明此時備庫數據庫異常。在後續狀態中反反覆覆的發生狀態變化,最後狀態變成了catchingup,表示備庫一直在狀態主庫,此時也可以説明備庫數據庫環境出現了一段時間的不穩定現象。
查看主庫的pg_auto_failover日誌的信息,詳細信息如下:

主庫在相同的時間提示主庫的狀態從primary轉到wait_primary,跟備庫的日誌時間可以對應上。
通過上面日誌可以説明監控節點到兩台PG服務器之間網絡肯定沒有問題,其中備庫服務器也並未異常。

2.2、 備庫日誌分析

2.2.1、 亂碼日誌分析

分析在上面提到的故障時間點備庫日誌消息信息,詳細日誌如下:

2025-04-01 13:02:16.451 CST [1587210] ????:  ?????? "192.168.111.12", ?? "postgres", ??? "postgres", no encryption ? pg_hba.conf ??
2025-04-01 14:13:28.203 CST [1455865] ??:  ????? (fast) ????
2025-04-01 14:13:28.209 CST [1455865] ??:  ????????
2025-04-01 14:13:28.927 CST [1455868] ??:  ????
2025-04-01 14:13:28.961 CST [1455865] ??:  ????????

日誌文件有大量上面重複的內容,通過保存下來的英語文字,大概可以推斷應該是連接備庫有問題了。
繼續往下分析日誌,有如下的日誌:

2025-04-01 15:07:45.304 CST [1686586] ??:  ??????????????????
2025-04-01 15:07:45.304 CST [1686586] ??:  ????? (immediate) ????
2025-04-01 15:07:45.304 CST [1686586] ??:  ?????? "postmaster.pid": ENOENT
2025-04-01 15:07:45.319 CST [1686586] ??:  ????????
2025-04-01 15:07:45.329 CST [1727667] ??:  ???? PostgreSQL 14.9 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 7.3.0, 64-bit
2025-04-01 15:07:45.329 CST [1727667] ??:  ????IPv4??"0.0.0.0",?? 1821
2025-04-01 15:07:45.329 CST [1727667] ??:  ????IPv6??"::",?? 1821
2025-04-01 15:07:45.329 CST [1727667] ??:  ?????? "postmaster.pid": ENOENT
2025-04-01 15:07:45.330 CST [1727667] ??:  ?Unix??? "/var/run/postgresql/.s.PGSQL.1821"???
2025-04-01 15:07:45.330 CST [1727667] ??:  ?????? "postmaster.pid": ENOENT
2025-04-01 15:07:45.330 CST [1727667] ??:  ?Unix??? "/tmp/.s.PGSQL.1821"???
2025-04-01 15:07:45.333 CST [1727667] ??:  ?????? "postmaster.pid": ENOENT
2025-04-01 15:07:45.334 CST [1727670] ??:  ?????2025-04-01 14:31:41 CST?????,????????
2025-04-01 15:07:45.334 CST [1727670] ??:  ??????????,????????????,????????????????

這裏看到備庫數據庫有重啓的操作,重啓以後還是無法連接。

2.2.2、 正常日誌分析

簡單調整環境後得到下面的日誌內容:

2025-04-02 09:42:05.780 CST [2895370] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:05.903 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:07.786 CST [2895372] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:09.795 CST [2895438] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:10.906 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:11.803 CST [2895497] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:13.809 CST [2895567] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:15.818 CST [2895638] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:15.910 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:17.825 CST [2895689] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:19.831 CST [2895708] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:20.915 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法
2025-04-02 09:42:22.188 CST [2895730] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:24.194 CST [2895731] 致命錯誤:  數據庫系統啓動中
2025-04-02 09:42:25.919 CST [1952298] 日誌:  在456/7ECCB34D8處的資源管理器ID54不合法

這裏提示資源管理54不合法。

2.3、 資源管理器54分析

在PG中資源管理分為自定義和系統內置的,其中內置的資源管理器ID為0~21,自定義的資源管理ID為128-255。在備庫應用日誌時,會判斷資源ID是否合法,如果合法繼續往後面執行,如果非法,直接拋出異常。此時的ID 54並不在內置和自定的資源管理器中,所以被定義為異常ID,直接報錯。可以參看如下的源代碼:

#undef PG_RMGR
#define RM_MAX_ID			UINT8_MAX
#define RM_MAX_BUILTIN_ID	(RM_NEXT_ID - 1)
#define RM_MIN_CUSTOM_ID	128
#define RM_MAX_CUSTOM_ID	UINT8_MAX
#define RM_N_IDS			(UINT8_MAX + 1)

#define RM_N_CUSTOM_IDS		(RM_MAX_CUSTOM_ID - RM_MIN_CUSTOM_ID + 1)

static inline bool
內置資源ID的判斷
RmgrIdIsBuiltin(int rmid)
{
	return rmid <= RM_MAX_BUILTIN_ID;
}
 
static inline bool
自定義資源ID的判斷
RmgrIdIsCustom(int rmid)
{
	return rmid >= RM_MIN_CUSTOM_ID && rmid <= RM_MAX_CUSTOM_ID;
}
判斷資源ID是否合規
#define RmgrIdIsValid(rmid) (RmgrIdIsBuiltin((rmid)) || RmgrIdIsCustom((rmid)))

/*
 * RmgrId to use for extensions that require an RmgrId, but are still in

下面在看看日誌應用的代碼:

if (!RmgrIdIsValid(record->xl_rmid))
	{
		report_invalid_record(state,
							  "invalid resource manager ID %u at %X/%08X",
							  record->xl_rmid, LSN_FORMAT_ARGS(RecPtr));
		return false;
	}

如果資源ID異常,拋出上面的錯誤,並返回false。

3、 原因分析

備庫的WAL日誌文件來由主庫通過網絡傳遞給備庫,並且在異常前,有數據庫鏈接不上等異常的信息,所以導致WAL日誌損壞的原因有很多種。在當前環境中主庫暫時未開啓歸檔日誌,所以暫時無法獲得歷史的WAL日誌用於驗證WAL損壞發生在那個環境。下面我們簡單羅列幾個WAL損壞的原因:

  • 網絡丟包,導致包傳輸不完整。
  • 操作系統IO寫丟失。
  • 內存損壞

4、 解決方案

由於主庫WAL日誌丟失,所以暫時選擇重新搭建整個容災環境。

------------------作者介紹-----------------------

姓名:黃廷忠

現就職:Oracle中國高級服務團隊

曾就職:OceanBase、雲和恩墨、東方龍馬等