大家好，今天和大家聊聊上周发生在身边的一起数据丢失的诡异事件。
大致是上周四接到开发小伙伴的发的消息询问数据库UAT环境是否进行了还原，因为他之前精心准备的数据不见了。
从DBA的工作流程上说UAT测试环境属于松散式的管理，既不会备份数据库，更谈不上还原数据库。
本想让他自己解决的，但是这几张表里的数据貌似之前精心准备的测试数据，加上平时同事关系也不错。就想办法试试如何恢复几张表的数据。
由于没有备份，我这边能想到的是类似于 log miner的东西，在指定的时间内把它们的记录从WAL log中挖出来：
PG拥有强大的插件生态，我很快的找到了WALIMNER, 这个插件最早是由国内瀚高研发的，现在是有私人在维护。
下载的时候一定要注意版本： version 3.0是stable 稳定版而且是免费的 支持到PG15。
walminer 最新版是4.0+版本，需要licence. 有企业版和个人版之分。
walminer 3.0的下载地址： https://gitee.com/movead/XLogMiner/repository/archive/walminer_3.0_stable.zip
插件的安装方式和PG其他的插件是一样的，拷贝到源码的contrib路径下，进行编译
make && make install
接下来，我们创建插件：
postgres=# create extension walminer;
CREATE EXTENSION
根据开发同学提供的信息，数据插入的时间范围在 2023-12-15 00:00:00 - 2023-12-16 00:00:00
我们从pg_wal的文件夹下找到了相关的 WAL log 文件列表：
-rw------- 1 postgres postgres 16M Dec 14 00:51 00000003000000D200000084
-rw------- 1 postgres postgres 16M Dec 15 00:00 00000003000000D200000085
-rw------- 1 postgres postgres 16M Dec 15 00:03 00000003000000D200000086
-rw------- 1 postgres postgres 16M Dec 15 00:05 00000003000000D200000087
-rw------- 1 postgres postgres 16M Dec 15 00:06 00000003000000D200000088
-rw------- 1 postgres postgres 16M Dec 15 00:07 00000003000000D200000089
-rw------- 1 postgres postgres 16M Dec 15 00:08 00000003000000D20000008A
-rw------- 1 postgres postgres 16M Dec 15 00:09 00000003000000D20000008B
-rw------- 1 postgres postgres 16M Dec 15 00:09 00000003000000D20000008C
-rw------- 1 postgres postgres 16M Dec 15 00:11 00000003000000D20000008D
-rw------- 1 postgres postgres 16M Dec 15 00:13 00000003000000D20000008E
-rw------- 1 postgres postgres 16M Dec 15 00:15 00000003000000D20000008F
-rw------- 1 postgres postgres 16M Dec 15 00:50 00000003000000D200000090
-rw------- 1 postgres postgres 16M Dec 16 00:00 00000003000000D200000091
-rw------- 1 postgres postgres 16M Dec 16 00:02 00000003000000D200000092
我们通过函数 walminer_wal_add，这符合时间范围内的WAL log 注册进去：
select walminer_wal_add('/data/pgdata/15/data/pg_wal/00000003000000D200000084');
...
...
select walminer_wal_add('/data/pgdata/15/data/pg_wal/00000003000000D200000092');
通过函数walminer_all()进行解析：
db_plumc=# select walminer_all();
NOTICE: Switch wal to 00000003000000D200000085 on time 2023-12-21 21:52:43.063421+08
NOTICE: Switch wal to 00000003000000D200000086 on time 2023-12-21 21:52:43.137475+08
NOTICE: Switch wal to 00000003000000D200000087 on time 2023-12-21 21:52:43.278437+08
NOTICE: Switch wal to 00000003000000D200000088 on time 2023-12-21 21:52:43.447463+08
NOTICE: Switch wal to 00000003000000D200000089 on time 2023-12-21 21:52:43.592441+08
NOTICE: Switch wal to 00000003000000D20000008A on time 2023-12-21 21:52:43.703794+08
NOTICE: Switch wal to 00000003000000D20000008B on time 2023-12-21 21:52:43.825194+08
NOTICE: Switch wal to 00000003000000D20000008C on time 2023-12-21 21:52:43.932537+08
NOTICE: Switch wal to 00000003000000D20000008D on time 2023-12-21 21:52:44.066103+08
NOTICE: Switch wal to 00000003000000D20000008E on time 2023-12-21 21:52:44.214081+08
NOTICE: Switch wal to 00000003000000D20000008F on time 2023-12-21 21:52:44.354966+08
NOTICE: Switch wal to 00000003000000D200000090 on time 2023-12-21 21:52:44.509338+08
NOTICE: Switch wal to 00000003000000D200000091 on time 2023-12-21 21:52:44.635369+08
NOTICE: Switch wal to 00000003000000D200000092 on time 2023-12-21 21:52:44.700842+08
...
最后我们通过walminer_contents查看一下解析出来的SQL结果， 很失望，没有找到相关表的 insert 语句
只有一些登录的trace log的记录。
db_plumc=# select * from walminer_contents ;
sqlno | xid | topxid | sqlkind | minerd | timestamp |
op_text
|
undo_text
| complete | schema | relation | start_lsn | commit_lsn
-------+----------+--------+---------+--------+-------------------------------+--------------------------------------
---------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------+-------------------------------
---------------------------------------------------------------------------------------------------------------------
+----------+-----------+----------------+-------------+-------------
1 | 23983272 | 0 | 1 | t | 2023-12-14 13:22:49.047097+08 | INSERT INTO app_plumc.sys_logininfor(
info_id ,user_name ,ipaddr ,login_location ,browser ,os ,status ,msg ,login_time) VALUES(301 ,'admin' ,'127.0.0.1' ,'
内网IP' ,'Unknown' ,'Unknown' ,'0' ,'登录成功' ,'2023-12-14 13:22:49.045564') | DELETE FROM app_plumc.sys_logi
ninfor WHERE info_id=301
| t | app_plumc | sys_logininfor | D2/85890160 | D2/85893028
1 | 23983273 | 0 | 2 | t | 2023-12-14 13:22:49.049058+08 | UPDATE app_plumc.sys_user SET login_d
ate='2023-12-14 13:22:49.028', update_time='2023-12-14 13:22:49.045838' WHERE user_id=1
| UPDATE app_plumc.sys_user SET
login_date='2023-12-13 18:15:24.484', update_time='2023-12-13 18:15:24.502843' WHERE user_id=1
| t | app_plumc | sys_user | D2/85893028 | D2/85893160
1 | 24341852 | 0 | 1 | t | 2023-12-15 10:05:41.765047+08 | INSERT INTO app_plumc.sys_logininfor(
info_id ,user_name ,ipaddr ,login_location ,browser ,os ,status ,msg ,login_time) VALUES(302 ,'admin' ,'10.64.92.38'
,'内网IP' ,'Chrome 10' ,'Windows 10' ,'0' ,'登录成功' ,'2023-12-15 10:05:41.763365') | DELETE FROM app_plumc.sys_logi
ninfor WHERE info_id=302
| t | app_plumc | sys_logininfor | D2/918CA538 | D2/918CD440
1 | 24341853 | 0 | 2 | t | 2023-12-15 10:05:41.767895+08 | UPDATE app_plumc.sys_user SET login_i
p='10.64.92.38', login_date='2023-12-15 10:05:41.761', update_time='2023-12-15 10:05:41.76752' WHERE user_id=1
| UPDATE app_plumc.sys_user SET
login_ip='127.0.0.1', login_date='2023-12-14 13:22:49.028', update_time='2023-12-14 13:22:49.045838' WHERE user_id=1
| t | app_plumc | sys_user | D2/918CD440 | D2/918CD578
1 | 24342015 | 0 | 2 | t | 2023-12-15 13:33:14.911489+08 | UPDATE app_plumc.sys_user SET login_d
ate='2023-12-15 13:33:14.909', update_time='2023-12-15 13:33:14.910919' WHERE user_id=1
| UPDATE app_plumc.sys_user SET
login_date='2023-12-15 10:05:41.761', update_time='2023-12-15 10:05:41.76752' WHERE user_id=1
| t | app_plumc | sys_user | D2/91957968 | D2/91957AA0
1 | 24342016 | 0 | 1 | t | 2023-12-15 13:33:14.916088+08 | INSERT INTO app_plumc.sys_logininfor(
info_id ,user_name ,ipaddr ,login_location ,browser ,os ,status ,msg ,login_time) VALUES(303 ,'admin' ,'10.64.92.38'
,'内网IP' ,'Chrome 10' ,'Windows 10' ,'0' ,'登录成功' ,'2023-12-15 13:33:14.91452') | DELETE FROM app_plumc.sys_logi
ninfor WHERE info_id=303
| t | app_plumc | sys_logininfor | D2/91957B08 | D2/9195AA60
1 | 24342017 | 0 | 1 | t | 2023-12-15 13:39:11.737274+08 | INSERT INTO app_plumc.sys_logininfor(
info_id ,user_name ,ipaddr ,login_location ,browser ,os ,status ,msg ,login_time) VALUES(304 ,'admin' ,'10.64.92.38'
,'内网IP' ,'Chrome 10' ,'Windows 10' ,'0' ,'退出成功' ,'2023-12-15 13:39:11.736342') | DELETE FROM app_plumc.sys_logi
ninfor WHERE info_id=304
| t | app_plumc | sys_logininfor | D2/9195AA98 | D2/9195AC10
(7 rows)
难道是这个插件有问题？ 还是开发同学提供的信息有误？
从DBA自身的角度，想到了另外的一个极端方式 ， 从OS 级别的 page中读取数据， github上有相关的工具 pg_filedump
链接地址： https://github.com/df7cb/pg_filedump
下载之后安装也很简单：
make && make install
这个工具使用也很简单，直接找打表相关文件的路径：
db_plumc=# select pg_relation_filepath('t_collection_phase');
pg_relation_filepath
----------------------
base/59150/67663
(1 row)
我们使用命令: pg_filedump -D （列的类型列表，逗号分隔） 文件路径
解析后的文件我们临时保存在 /tmp/t_collection_phase.rec
/opt/pgsql-15/bin/pg_filedump -D numeric,text,numeric,numeric,numeric,text,text,text,text,text,text,numeric,text,timestamp,text,timestamp /data/pgdata/15/data/base/59150/67663 | grep COPY | awk '{$1=null;print $0}'>/tmp/t_collection_phase.rec
我们查看解析的文件： 是有2条数据，并且可以清晰的看到数据插入的时间 是2023-12-15 14:35:33.265575
INFRA [postgres@wqdcsrv3084 pg_wal]# view /tmp/t_collection_phase.rec
1 DefaultPhase 0 1 1 Default_Phase 默认催收阶段 and 1=1 and 1=1 and 1=2 and 1=2 999 Mars 2023-12-15 14:35:33.265575 Mars 2023-12-15 14:35:33.265575
2 PreCollection 0 1 0 Pre_Collection 预催收阶段 and PASTDUEAMOUNT > 0 and PASTDUEAMOUNT > 0 and PASTDUEAMOUNT <= 0 and PASTDUEAMOUNT <= 0 1 Mars 2023-12-15 14:35:33.265575 Mars 2023-12-15 14:35:33.265575
于是我们再次找到开发同学进行确认：
恢复很简单，我们对文件/tmp/t_collection_phase.rec 进行一下简单的处理，变成CSV的格式 copy到表中即可。
copy t_collection_phase from '/tmp/t_collection_phase.rec'(DELIMITER ',');
在处理另外几张表的时候，发现有numeric(m,n)这种类型的转换问题： 出现了这种格式 8550.C723 不知道是什么原因，个别字段的问题只能交给开发自己修理了。
在github 提了issue, 感觉回复概率很低： https://github.com/df7cb/pg_filedump/issues/26
目前总结：
- 目前还是不能确认是什么原因造成的WAL中没有相关的数据。
- pg_filedump 是在没有备份，没有WAL 日志，数据库不能正常启动的情况下的一种基于OS文件级别解码， 恢复的数据的完整性和正确性是不能保证的。 但是数据不准确总比数据是零强。
后记：
个人感觉WAL是不可能丢失数据库， 有没有一种可能开发同学当初的SQL没有提交呢？
我们做一个实验模拟一下：
模拟一条rollback的日志, 产生一条 n_dead_tup:
db_plumc=# create table t2 (id int, name varchar(100));
CREATE TABLE
db_plumc=# begin;
BEGIN
db_plumc=# insert into t2 select 1, 'jason' ;
INSERT 0 1
db_plumc=# rollback;
ROLLBACK
db_plumc=# select * from t2;
id | name
----+------
(0 rows)
db_plumc=# select n_tup_ins,n_tup_upd,n_tup_del,n_live_tup,n_dead_tup from pg_stat_user_tables where relname ='t2';
n_tup_ins | n_tup_upd | n_tup_del | n_live_tup | n_dead_tup
-----------+-----------+-----------+------------+------------
1 | 0 | 0 | 0 | 1
(1 row)
我们通过walminer 来挖一下： 确实和我们的猜想一样是decoding 不到这条记录的
db_plumc=# checkpoint;
CHECKPOINT
db_plumc=# select walminer_wal_add('/data/pgdata/15/data/pg_wal/00000003000000D2000000EB');
walminer_wal_add
--------------------
1 file add success
(1 row)
db_plumc=# select walminer_all();
NOTICE: Switch wal to 00000003000000D2000000EB on time 2023-12-22 10:57:00.332643+08
walminer_all
---------------------
pg_minerwal success
(1 row)
db_plumc=# select * from walminer_contents tt where tt.op_text ~~ '%t2%';
sqlno | xid | topxid | sqlkind | minerd | timestamp | op_text | undo_text | complete | schema | relation | start_lsn | commit_lsn
-------+-----+--------+---------+--------+-----------+---------+-----------+----------+--------+----------+-----------+------------
(0 rows)
又经过和walminer的作者核实确认，walminer 3.0目前是不可以找到rollback的记录的。
我们再次利用pg_filedump这个工具来试试，能不能找回未提交的数据： 果然可以找回来！
db_plumc=# select pg_relation_filepath('t2');
pg_relation_filepath
----------------------
base/59150/68141
(1 row)
INFRA [postgres@wqdcsrv3084 pg_wal]# /opt/pgsql-15/bin/pg_filedump -D int,text /data/pgdata/15/data/base/59150/68141 | grep COPY | awk '{$1=null;print $0}'>/tmp/t2.rec
INFRA [postgres@wqdcsrv3084 pg_wal]# view /tmp/t2.rec
1 jason
最后我们回到UAT的环境里有插件pageinspect 查看一下表t_collection_phase 当时插入的记录是否提交：
我们看到有 4个 n_tup_ins 插入记录， n_live_tup =2 是我这边通过pg_filedump 手动copy回去的
目前n_dead_tup =2 高度可疑
db_plumc=# select n_tup_ins,n_tup_upd,n_tup_del,n_live_tup,n_dead_tup from pg_stat_user_tables where relname ='t_collection_phase';
n_tup_ins | n_tup_upd | n_tup_del | n_live_tup | n_dead_tup
-----------+-----------+-----------+------------+------------
4 | 0 | 0 | 2 | 2
(1 row)
n_dead_tup =2， 果然是没有提交:HEAP_XMIN_COMMITTED = f
select lp,lp_off,lp_flags,lp_len,t_xmin,t_xmax,t_ctid,(t_infomask & 256)::boolean AS HEAP_XMIN_COMMITTED from heap_page_items(get_raw_page('t_collection_phase',0));
最后和开发同学核实是存储过程中逻辑bug造成的，事务没有提交，进行了回滚。
Have a fun 😃 ！
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。
