谁是linux SIGKILL的凶手---linux审计日志排障的杀手锏

一、背景描述

在我们的技术生涯中，总会碰到那精彩的一瞬间，哪怕是一瞬间，曾经的熟悉php内核的同事和今天碰到的排障瞬间，都是我技术生涯中那精彩的一瞬间，写一篇日志记录一下。

今天碰到一个问题，就是采集器的agent 总是被另一个进程在5分钟之后杀掉

具体现象

# sudo strace -p 6574
strace: Process 6574 attached
restart_syscall(<... resuming interrupted read ...>

过了一会收到SIGKILL 信号

# sudo strace -p 6574
strace: Process 6574 attached
restart_syscall(<... resuming interrupted read ...>) = ?
+++ killed by SIGKILL +++

那么我们现在面临的问题是如何找到发送SIGKILL的真凶。我们知道linux 信号里和其他信号还不一样，比如说SIGTERM 是可捕获的，SIGKILL 是不可捕获的，当进程收到信号的时候进程会被操作系统强制杀掉，这也给我排障带来了很大的障碍。

二、谁是SIGKILL真凶的搜查之旅

1）初步使用strace 排障

当出现这个问题的时候我们使用strace 进行排障

具体命令如下

$ sudo strace -p 7000 -e trace=signal

具体排查效果

strace: Process 7000 attached
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=6672, si_uid=1000} ---
+++ killed by SIGTERM +++

 我们发现使用strace 可以很成功的捕获SIGTERM这一类的可捕获信号，但是当我们捕获SIGKILL的时候

$ sudo strace -p 7220 -e trace=signal
strace: Process 7220 attached
+++ killed by SIGKILL +++

发现SIGKILL被捕捉不了

总结：

使用strace 只可以捕获客捕捉的信号，当我们使用不可捕捉信号的时候strace 就已经回天乏术了

2）查看linux 内核相关日志查找SIGKILL信息

去 /var/log/messages 和 journalctl 也没查到相关日志

3）开启linux信号跟踪，找到发送信号的进程号

# 进入目录
cd /sys/kernel/debug/tracing/

# 过滤SIGKILL
echo 'sig==9' > events/signal/signal_generate/filter 

# 开启过滤
echo '1' > events/signal/signal_generate/enable

# 开启tracing_on
echo '1' > tracing_on

我们可以查看tracing 目录下面trace 查看是谁发起的SIGKILL的信号

# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:16
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
            bash-6558    [008] d..1.  2476.431621: signal_generate: sig=9 errno=0 code=0 comm=sleep pid=8784 grp=1 res=0

我们发现是linux的6558 发出的SIGKILL 信号杀掉了8784。

但是重点来了，我们知道是6558调用 kill 命令发出SIGKILL信号，但是6558 是一个子进程，他被父进程使用后立马被回收了，我们如何定位到调用6558 的父进程呢？、

我想过使用BCC EBPF 去HOOK linux 内核的exec clone 一类的函数去追查真凶，但是用户的linux主机中并没有bcc，无法使用ebpf，这时候我较劲脑汁也无法查找出最后的根因，真的没办法了吗？

三、精彩的一瞬-----linux审计日志排障

当我不知所措的时候一个搞了20多年的内核程序员说，你为什么不打开审计日志呢？这精彩的一瞬在这一刻让我找到了问题的真凶。就像一局棋，这一笔就是画龙点睛的最后一步，他找到了最后的真凶。

我们可是梳理思路能不能从系统调用的execve 这一侧找到问题的根因呢？我们使用审计日志审查SIGKILL的发出者以及execve的使用者，双管齐下找到了最后的真凶。具体步骤如下：

1）提前安装审计日志程序

sudo apt install auditd

2）添加审计日志规则

定位ls 用了哪个系统调用

# strace ls
execve("/usr/bin/ls", ["ls"], 0x7ffcd8de3d10 /* 49 vars */) = 0
brk(NULL)                               = 0x55d7dade2000

我们使用进程的时候会调用execve，于是我们添加审计日志

vi /etc/audit/rules.d/audit.rules

-a exit,always -F arch=b64 -F a1=9 -S kill -k sigkill
-a exit,always -F arch=b32 -F a1=9 -S kill -k sigkill
-a exit,always -F arch=b64 -F a1=15 -S kill -k sigterm
-a exit,always -F arch=b32 -F a1=15 -S kill -k sigterm
-a exit,always -F arch=b64 -F a1=19 -S kill -k sigstop
-a exit,always -F arch=b32 -F a1=19 -S kill -k sigstop
-a always,exit -F arch=b64 -S execve -k exec
-a always,exit -F arch=b32 -S execve -k exec

-a exit,always：表示无论系统调用是否成功，都会记录事件。

-F arch=b32：指定CPU架构为32位系统。

-F a1=15：表示系统调用的第一个参数为15，即SIGTERM信号。

-S kill：表示监视kill系统调用。

-k sigterm：使用"sigterm"作为事件的键值。

修改完成规则后我们重启审计日志服务：

service auditd restart

3)查看审计日志

/var/log/audit/audit.log

我们用sleep 为例：

type=SYSCALL msg=audit(1704732268.057:196): arch=c000003e syscall=59 success=yes exit=0 a0=55e92bc5bc30 a1=55e92bc5f7c0 a2=55e92bc57110 a3=8 items=2 ppid=7356 pid=11663 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts2 ses=2 comm="sleep" exe="/usr/bin/sleep" subj=unconfined key="exec"ARCH=x86_64 SYSCALL=execve AUID="zhanglei" UID="root" GID="root" EUID="root" SUID="root" FSUID="root" EGID="root" SGID="root" FSGID="root"

最后通过审计日志我们一步步找到了kill 调用的父进程，最终找到了使用Kill 发送 SIGKILL的真凶

四、总结

在没有ebpf 的情况下，我们可以使用strace 找到相关系统调用，然后进一步使用审计日志，找到问题出现的根源，从而解决问题。