我们的文章会在微信公众号IT民工的龙马人生和博客网站( www.htz.pw )同步更新 ,欢迎关注收藏,也欢迎大家转载,但是请在文章开始地方标注文章出处,谢谢!
由于博客中有大量代码,通过页面浏览效果更佳。
今天这个故障感觉有点奇怪,突然PG就报归档日志错误了。我们都知道PG的归档操作是非常的灵活,完全可以由用户自定义,也是自定义灵活,所以引发了很多故障,有些隐患及时发现了,有些隐患只有在出现重大故障时才能发现,就如本次这个故障,如果没有提示归档失败,后续数据库如果要事故时,就会遇到归档日志文件损坏,数据库无法恢复的重大事故,所以我们常常会说一句话:系统没有隐患,可能是由于自己能力不足没有发现,但并不代表系统没有隐患。
1 故障现象
后台日志文件提示归档失败,原因是归档命令返回1的错误,通过重试多少还是失败
/* by 01022.hk - online tools website : 01022.hk/zh/imagetojpg.html */
2025-07-28 18:27:34.147 CST,,,29398,,68874fdc.72d6,13,,2025-07-28 18:24:28 CST,,0,LOG,00000,"archive command failed with exit code 1","The failed archive command was: test ! -f /postgresql/archive/1721/000000080000002600000006 && cp pg_wal/000000080000002600000006 /postgresql/archive/1721/000000080000002600000006",,,,,,,"pgarch_archiveXlog, pgarch.c:589","","archiver",,0
2025-07-28 18:27:35.151 CST,,,29398,,68874fdc.72d6,14,,2025-07-28 18:24:28 CST,,0,LOG,00000,"archive command failed with exit code 1","The failed archive command was: test ! -f /postgresql/archive/1721/000000080000002600000006 && cp pg_wal/000000080000002600000006 /postgresql/archive/1721/000000080000002600000006",,,,,,,"pgarch_archiveXlog, pgarch.c:589","","archiver",,0
2025-07-28 18:27:36.155 CST,,,29398,,68874fdc.72d6,15,,2025-07-28 18:24:28 CST,,0,LOG,00000,"archive command failed with exit code 1","The failed archive command was: test ! -f /postgresql/archive/1721/000000080000002600000006 && cp pg_wal/000000080000002600000006 /postgresql/archive/1721/000000080000002600000006",,,,,,,"pgarch_archiveXlog, pgarch.c:589","","archiver",,0
2025-07-28 18:27:36.155 CST,,,29398,,68874fdc.72d6,16,,2025-07-28 18:24:28 CST,,0,WARNING,01000,"archiving write-ahead log file ""000000080000002600000006"" failed too many times, will try again later",,,,,,,,"pgarch_ArchiverCopyLoop, pgarch.c:486","","archiver",,0
这里提示次数很多,稍后再试了。
2 故障分析
2.1 查询统计信息
在archiver的视图中可以看到报错的次数,上次报错的wal文件及报错时间。
/* by 01022.hk - online tools website : 01022.hk/zh/imagetojpg.html */
postgres_1721@postgres > SELECT * FROM pg_stat_archiver;
archived_count | last_archived_wal | last_archived_time | failed_count | last_failed_wal | last_failed_time | stats_reset
----------------+--------------------------+-------------------------------+--------------+--------------------------+-------------------------------+-------------------------------
31 | 000000080000002A00000004 | 2025-07-28 21:15:14.949197+08 | 2704 | 000000080000002600000006 | 2025-07-28 21:12:59.153555+08 | 2025-07-28 06:15:08.470418+08
2.2 确认备份命令错误
手动执行备份命令,确认备份命令是否报错
[root@pgc ~]# test ! -f /postgresql/archive/1721/000000080000002600000006 && cp pg_wal/000000080000002600000006 /postgresql/archive/1721/000000080000002600000006
[root@pgc ~]# echo $?
1
这里看到整个命令返回1的错误,说明跟数据库后台日志报错一样。
查看归档日志文件已经存在了。
[root@pgc ~]# ls -l /postgresql/archive/1721/000000080000002600000006
-rw-------. 1 postgres postgres 136314880 Jul 28 05:42 /postgresql/archive/1721/000000080000002600000006
但是通过下面文件看到数据库并没有更新archvie_status文件,因为归档未完成。
[postgres@pgc pg_wal]$ ls -l $PGDATA/pg_wal/archive_status/000000080000002600000006*
-rw-------. 1 postgres postgres 0 Jul 28 05:42 archive_status/000000080000002600000006.ready
这里看到归档日志文件存在,但是数据库认为没有归档,那就只有一种情况,归档过程是触发了,但是归档还未完成就结束了,所以导致文件存在,但是状态文件未更新。
2.3 判断归档文件是否一致
通过操作系统的md5命令计算归档日志文件和wal文件收一致
[postgres@pgc pg_wal]$ md5sum /postgresql/archive/1721/000000080000002600000006
c16ac4d138a77800e3972343afc4d708 /postgresql/archive/1721/000000080000002600000006
[postgres@pgc pg_wal]$ md5sum 000000080000002600000006
b08d89927693e56987b73eaedaadce31 000000080000002600000006
这里看到归档日志文件跟wal的md5数据不一致,跟上面说的现象一模一样
3,解决方案
删除归档路径中的文件即可:
确定后续归档是否正常,这里看到文件已经完成归档了。
-rw-------. 1 postgres postgres 0 Jul 28 05:42 /postgresql/pgdata/14/15/1721/pg_wal/archive_status/000000080000002600000006.done
这里看到文件修改的时间为当前
File: /postgresql/pgdata/14/15/1721/pg_wal/archive_status/000000080000002600000006.done
Size: 0 Blocks: 0 IO Block: 4096 regular empty file
Device: fd00h/64768d Inode: 422963830 Links: 1
Access: (0600/-rw-------) Uid: ( 601/postgres) Gid: ( 601/postgres)
Context: unconfined_u:object_r:default_t:s0
Access: 2025-07-28 05:42:46.005917972 +0800
Modify: 2025-07-28 05:42:46.005917972 +0800
Change: 2025-07-28 21:13:59.538470918 +0800
Birth: 2025-07-28 05:42:46.005917972 +0800
pg_stat_archiver的状态还没有更新,需要等待一段时间才会更新
postgres_1721@postgres > SELECT * FROM pg_stat_archiver;
archived_count | last_archived_wal | last_archived_time | failed_count | last_failed_wal | last_failed_time | stats_reset
----------------+--------------------------+-------------------------------+--------------+--------------------------+-------------------------------+-------------------------------
46 | 000000080000002C00000003 | 2025-07-28 21:17:39.769599+08 | 2704 | 000000080000002600000006 | 2025-07-28 21:12:59.153555+08 | 2025-07-28 06:15:08.470418+08
(1 row)
手动触发归档操作,确保归档日志生成就可以了。
ls -l $PGARCH/
4,故障原因
为什么会出现归档日志写入一半后就终止了呢?是由于之前数据库在归档过程中,磁盘空间耗尽,数据库异常宕机,所以引发了归档日志写入一半就退出了。当删除历史归档日志后,数据库恢复正常,但是由于归档日志在操作系统上存在,所以引发了后续归档失败。
感觉PG在做归档时并没有校验归档目录空间是否有足够的空间存放当前归档文件,如果有做校验,那么可以在归档前就关闭数据库,此时就不会出现这种情况。当然这个文件要解决也是非常简单的,自己写一个脚本,在复制之前判断文件是否存在,存在就计算md5的值,判断是否一致,一致就退出,不一致就复制。
如下所示:
[postgres@pgc pg_wal]$ pg_archive.sh $PGARCH 000000080000002C00000000 $PGDATA/pg_wal/000000080000002C00000000
WAL file 000000080000002C00000000 already archived with matching MD5. Skipping.
[postgres@pgc pg_wal]$ pg_archive.sh $PGDATA 000000080000002C00000000 $PGDATA/pg_wal/000000080000002C00000000
WAL file 000000080000002C00000000 not archived yet. Archiving now.
如果需要获取脚本,请直接叫我微信:18081072613,我拉你入群,群里面有我所有的脚本分享。
5,总结
灵活的归档日志配置给了我们可以操作的空间,但是对我们的技术要求和经验也会更高,所有的技术都需要我们自己来严格把关,不然很可能弄出“花瓶”的环境,看着运行很好,其实有很大的隐患。
------------------作者介绍-----------------------
姓名:黄廷忠
现就职:Oracle中国高级服务团队
曾就职:OceanBase、云和恩墨、东方龙马等
电话、微信、QQ:18081072613
个人博客: (http://www.htz.pw)
优快云地址: (https://blog.youkuaiyun.com/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)