大家好，今天和大家聊聊上周发生在身边的一起数据丢失的诡异事件。
大致是上周四接到开发小伙伴的发的消息询问数据库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 😃 ！
【米乐app官网下载的版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。