PG故障处理：LOG: invalid resource manager ID 54故障处理

我们的文章会在微信公众号IT民工的龙马人生和博客网站 ( www.htz.pw )同步更新，欢迎关注收藏，也欢迎大家转载，但是请在文章开始地方标注文章出处，谢谢！
由于博客中有大量代码，通过页面浏览效果更佳。

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、云和恩墨、东方龙马等
电话、微信、QQ：18081072613
个人博客: (http://www.htz.pw)
CSDN地址: (https://blog.csdn.net/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)

posted @ 2025-09-09 00:54 认真就输阅读(8) 评论(0) 收藏举报

刷新页面返回顶部

PG故障处理：LOG: invalid resource manager ID 54故障处理

1、 故障现象

2、 故障分析

2.1、 查询failover工具日志

2.2、 备库日志分析

2.2.1、 乱码日志分析

2.2.2、 正常日志分析

2.3、 资源管理器54分析

3、 原因分析

4、 解决方案

公告