分析问题的同时顺手搞定一下挖矿病毒

xiongcc2022年11月16日约 8 分钟

前言

今天群里一位小伙伴提了这样一个案例：

“
现象：业务运行过程中会频繁创建写入删除大量的unlogged表，在业务运行过程中系统的sys cpu比较高（40%）user cpu比较低（5%），在对应的系统上产生了大量的文件（600w+），业务运行过程中手动触发checkpoint几个小时都无法正常结束，等待事件为CheckpointStart，这个checkpoint无法完成可能跟什么有关系？当业务运行结束后手动checkpoint很快能完成，系统上的文件也很快会回收到10w以内

我想着复现一下，结果发现我的小破云主机又被挖矿了！那就先解决一下这个病毒。

分析

不同于之前的案例，👉🏻 活久见，数据库里存病毒？这次的病毒会悄悄创建一个超级用户，然后将默认的 postgres 用户改为非 superuser，我特意重新初始化了一个数据库观察现象：

[postgres@xiongcc ~]$ pg_ctl -D pgdata/ start
waiting for server to start....2022-11-15 20:31:35.356 CST [31237] LOG:  starting PostgreSQL 14.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2022-11-15 20:31:35.356 CST [31237] LOG:  listening on IPv6 address "::1", port 5432
2022-11-15 20:31:35.356 CST [31237] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2022-11-15 20:31:35.361 CST [31237] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2022-11-15 20:31:35.366 CST [31238] LOG:  database system was shut down at 2022-11-15 20:31:30 CST
2022-11-15 20:31:35.369 CST [31237] LOG:  database system is ready to accept connections
 done
server started
[postgres@xiongcc ~]$ psql
psql (14.2)
Type "help" for help.postgres=# \du
                                   List of roles
 Role name |                         Attributes                         | Member of 
-----------+------------------------------------------------------------+-----------
 postgres  | Superuser, Create role, Create DB, Replication, Bypass RLS | {}
postgres=# \q
[postgres@xiongcc ~]$ psql
psql (14.2)
Type "help" for help.
postgres=> \du
                              List of roles
 Role name |                   Attributes                    | Member of 
-----------+-------------------------------------------------+-----------
 postgres  | Create role, Create DB, Replication, Bypass RLS | {}
 root_user | Superuser

可以看到数据库里莫名起来多了一个超级用户 root_user，并且 postgres 用户还变成了非 superuser，为了看是什么玩意在作祟，重新来一次并且打开全日志 log_statement = all

[postgres@xiongcc ~]$ cat pgdata/log/postgresql-2022-11-15_204513.log 
2022-11-15 20:45:13.729 CST [32352] LOG:  starting PostgreSQL 14.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2022-11-15 20:45:13.730 CST [32352] LOG:  listening on IPv6 address "::1", port 5432
2022-11-15 20:45:13.730 CST [32352] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2022-11-15 20:45:13.734 CST [32352] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2022-11-15 20:45:13.739 CST [32354] LOG:  database system was shut down at 2022-11-15 20:44:50 CST
2022-11-15 20:45:13.742 CST [32352] LOG:  database system is ready to accept connections
2022-11-15 20:45:16.725 CST [32363] LOG:  statement: SELECT r.rolname, r.rolsuper, r.rolinherit,
          r.rolcreaterole, r.rolcreatedb, r.rolcanlogin,
          r.rolconnlimit, r.rolvaliduntil,
          ARRAY(SELECT b.rolname
                FROM pg_catalog.pg_auth_members m
                JOIN pg_catalog.pg_roles b ON (m.roleid = b.oid)
                WHERE m.member = r.oid) as memberof
        , r.rolreplication
        , r.rolbypassrls
        FROM pg_catalog.pg_roles r
        WHERE r.rolname !~ '^pg_'
        ORDER BY 1;
2022-11-15 20:45:24.362 CST [32381] LOG:  execute lrupsc_11547_0: select usename, usesuper from pg_shadow;  👈🏻从此处开始
2022-11-15 20:45:24.366 CST [32384] LOG:  statement: CREATE ROLE root_user WITH LOGIN SUPERUSER PASSWORD '491a59125348c2fec3e18c1674253d6a';
2022-11-15 20:45:24.395 CST [32388] LOG:  execute lrupsc_11549_0: select usename from pg_shadow where usesuper = 't' and usename <> 'root_user';
2022-11-15 20:45:24.395 CST [32388] LOG:  statement: alter user "postgres" with nosuperuser

可以看到跑了这么几条语句

select usename, usesuper from pg_shadow;
CREATE ROLE root_user WITH LOGIN SUPERUSER PASSWORD '491a59125348c2fec3e18c1674253d6a';
select usename from pg_shadow where usesuper = 't' and usename <> 'root_user';
alter user "postgres" with nosuperuser

并且通过观察日志，还在跑一些SQL。不难理解：pg_shadow 里面存放的是用户名和加密后的密码，这个病毒通过定时扫描 pg_shadow 获取用户名和密码

2022-11-15 20:45:24.395 CST [32388] LOG:  statement: alter user "postgres" with nosuperuser
2022-11-15 20:46:24.361 CST [32464] LOG:  execute lrupsc_11550_0: select usename, usesuper from pg_shadow;
2022-11-15 20:46:24.366 CST [32467] LOG:  execute lrupsc_11551_0: select usename from pg_shadow where usesuper = 't' and usename <> 'root_user';
2022-11-15 20:47:24.362 CST [32531] LOG:  execute lrupsc_11552_0: select usename, usesuper from pg_shadow;
2022-11-15 20:47:24.367 CST [32534] LOG:  execute lrupsc_11553_0: select usename from pg_shadow where usesuper = 't' and usename <> 'root_user';
2022-11-15 20:48:24.364 CST [32598] LOG:  execute lrupsc_11554_0: select usename, usesuper from pg_shadow;
2022-11-15 20:48:24.371 CST [32601] LOG:  execute lrupsc_11555_0: select usename from pg_shadow where usesuper = 't' and usename <> 'root_user';

在以前的版本，用户名密码默认的加密方式是 md5，但是加密方式相对"简陋"，如下 👇🏻

postgres=# show password_encryption ;
 password_encryption 
---------------------
 md5
(1 row)
postgres=# create role r_test password 'hello123' login; 
CREATE ROLE
postgres=# select usename,passwd from pg_shadow where usename='r_test';   
 usename |               passwd                
---------+-------------------------------------
 r_test  | md5bb0d7bef45a0530ac529e7b43943a2d1
(1 row)postgres=# select 'md5'||md5('hello123r_test') as mypasswd,passwd,usename from pg_shadow where usename = 'r_test';
              mypasswd               |               passwd                | usename 
-------------------------------------+-------------------------------------+---------
 md5bb0d7bef45a0530ac529e7b43943a2d1 | md5bb0d7bef45a0530ac529e7b43943a2d1 | r_test
(1 row)

因此对于简单密码很容易就破解出来了。那么这个病毒藏在哪里呢，对于这种执行一下就结束的短进程该怎么去获取？这里就要推荐另外一个工具了：execsnoop

“
execsnoop是专门用于为追踪短时进程（瞬时进程）设计的工具；
它通过 ftrace 实时监控进程的 exec() 行为，并输出短时进程的基本信息，包括进程 PID、父进程 PID、命令行参数以及执行的结果。

github地址：https://github.com/brendangregg/perf-tools/blob/master/execsnoop，将上面的github的内容复制，然后写入execsnoop文件，并且加上x权限即可。让我们抓一下看看

[postgres@xiongcc ~]$ sudo ./execsnoop.sh 
Tracing exec()s. Ctrl-C to end.
Instrumenting sys_execve
   PID   PPID ARGS
   756    752 gawk -v o=1 -v opt_name=0 -v name= -v opt_duration=0 [...]
   757    755 cat -v trace_pipe
   780   1308 /usr/sbin/sshd -D -R
   786   1308 /usr/sbin/sshd -D -R
   808   1308 /usr/sbin/sshd -D -R
   814    813 awk /^(MemFree|Buffers|Cached):/ {free += $2}; END {print free} /proc/meminfo
   902    458 sleep 60
   926   1308 /usr/sbin/sshd -D -R
   929   1308 /usr/sbin/sshd -D -R
   942  1322 pg_mem
   ...
   ...

可以看到跑了个pg_mem，使用find搜索了一圈，最终在我的实例目录下面藏了个pg_mem的脚本，脚本具体的内容就不贴了，大致就是获取账号密码，试图获取有用信息然后发出去，删除了之后我的数据库就恢复正常了。

病毒处理好之后，我们再来看看这个小伙伴的问题，为什么Checkpoint耗时特别久？在他这个案例中，使用到了大量的unlogged表，并且用完就删了，我们知道在PostgreSQL中删除表/截断表之后，表对应的文件和索引等，会被抹零，留下一个空文件，然后在下一次checkpoint的时候删除。

在这个案例中，checkpoint"卡住"的时候系统中有600万个文件，让我们模拟一下，先构造很多空文件出来

[postgres@xiongcc ~]$ cat generate.sh 
#!/bin/bash
for i in {1..10000} 
do
        for j in {1..10000} 
        do
                psql -U postgres -c "CREATE unlogged TABLE barf${i}${j}(id SERIAL NOT NULL PRIMARY KEY )" -c "drop table barf${i}${j}"
        done
done

构造了38万个文件之后，可以看到统计文件数量就耗时约9s

[postgres@xiongcc 13892]$ time ls -l | wc -l
389909real    0m9.120s
user    0m2.449s
sys     0m5.591s

这个时候做一下checkpoint，并抓一下堆栈

我和这位小伙伴要了一下问题时的堆栈，基本一致

再抓一下等待事件，可以看到有 CheckpointStart 和 CheckpointDone

CheckpointDone：Waiting for a checkpoint to complete，等待checkpoint结束
CheckpointStart：Waiting for a checkpoint to start，等待checkpoint开始

Wed 16 Nov 2022 10:26:32 AM CST (every 0.5s)   wait_event    | wait_event_type 
-----------------+-----------------
 CheckpointStart | IPC
(1 row)
...
Wed 16 Nov 2022 10:27:11 AM CST (every 0.5s)
   wait_event   | wait_event_type 
----------------+-----------------
 CheckpointDone | IPC
(1 row)
Wed 16 Nov 2022 10:27:12 AM CST (every 0.5s)
   wait_event   | wait_event_type 
----------------+-----------------
 CheckpointDone | IPC
(1 row)
...
Wed 16 Nov 2022 10:27:51 AM CST (every 0.5s)
   wait_event   | wait_event_type 
----------------+-----------------
 CheckpointDone | IPC
(1 row)
Wed 16 Nov 2022 10:27:52 AM CST (every 0.5s)
 wait_event | wait_event_type 
------------+-----------------
 ClientRead | Client
(1 row)

checkpoint 完成大概花费了90s，换算一下，40万花费90s，那么600万1350秒，大概20分钟，并且这是理想的状态下，我这个测试环境将 checkpoint_timeout 设置为了300m，为了在构建的过程中不要执行 checkpoint，假如实际系统中还有大量脏页，这个过程还会更久，600万个文件遍历统计一次都需要耗时很久。

这个其实和 WAL 的归档类似，归档进程需要遍历所有的 ready 文件并找到最老的文件，假如是高负载的服务器并且磁盘比较搓，归档可能落后了几千个 WAL，这样每一次遍历就会耗时很久，然后恶性循环，笔者曾经的项目，分布式数据库，往 HDFS 上备份，遇到过归档速度远远跟不上生成速度的，最终就放弃了PITR这个方案，采用定时逻辑备，牺牲一部分的 RPO。

小结

这个问题要解决的话，更多得从业务侧去进行整改，数据库层面让 checkpoint 触发更快一点或许可以缓解这个问题，但是治标不治本，checkpoint 本身耗时就很久，并且 checkpoint 频繁了，WAL 写放大的问题会更严重，IO 尖刺也会更加明显，所以这是一个 trade-off 。

前言

分析

小结

来自同一个声音

PGSimCity - PostgreSQL 工作原理可视化解析

从 Lakebase 到 LTAP，是旧饭新炒，还是新的技术范式？

AI 时代首选数据库：PostgreSQL 入门到进阶实战

pg-slide-harvester：自动收集 PG 大会演讲资料