本文讲述了Jochen Sprickerhof、Helmut Grohne和作者共同进行的一项调试调查。这是一次真正的团队合作，如果单独工作，他们可能无法找到问题的根源。作者认为这个故事很有趣，因此撰写了这篇简短的文章。其中一些步骤花费了几天时间，另一些步骤则只花了短短几分钟。文中描述的事件发展过程并非一直很明显。
让我们一起回顾一下这六个调试阶段。
**阶段1：不可能发生的事情**
11月底，Debian官方GCC构建在多个架构上开始失败。
构建错误发生在构建服务器上，在运行测试套件时出现。但作者知道这种情况不应该发生，因为GCC构建不应该因为测试套件失败而失败！返回值并不会导致构建失败，make命令使用-k参数，所以这种情况不应该发生。
实际上，许多GCC测试总是会失败，并且会在debian-gcc邮件列表中发布详细的日志，但无论如何，包总是可以正常构建。
在构建守护进程上，构建失败需要花费数小时。
**阶段2：在我的机器上不会发生**
在作者的Bookworm系统上构建一切正常。构建守护进程运行Bookworm，并使用Sid chroot作为构建环境，与作者的设置相同，内核也相同。
Debian包由一个名为sbuild的程序在网络中的自动构建机器上构建。作者在上一篇博文中提到了从schroot后端迁移到基于unshare的新后端的转换。
作者的设置与Debian构建机器之间的唯一明显区别在于，作者使用的是来自bookworm的sbuild 0.85.0版本，而构建机器使用的是来自bookworm-backports的0.86.3~bpo12+1版本。当作者尝试使用0.86.3~bpo12+1时，构建也在作者的系统上失败了。构建守护进程在11月底的某个时间点更新到了bookworm-backports版本的sbuild。
**阶段3：不应该发生**
在0.85.0和0.86.3~bpo12+1之间有相当多的sbuild版本，但查看最近的sbuild错误报告发现，sbuild 0.86.0“破坏了相当多的包”。确实，使用0.86.0构建仍然失败。尝试使用之前的版本0.85.11，构建成功完成。这花费的时间比看起来要长，包括测试在内的整个构建需要数小时。需要找到一种缩短构建时间的方法。
GCC的Debian打包允许指定要跳过的语言，默认情况下它构建Ada、Go、C、C++、D、Fortran、Objective C、Objective C++、M2和Rust。当按顺序运行测试时，构建日志在D的运行时库libphobos的测试附近停止。那么，是否可以通过只构建D来重现错误呢？使用DEB_BUILD_OPTIONS=nolang=ada,go,c,c++,fortran,objc,obj-c++,m2,rust，构建仍然失败，并且比之前更快。现在只需要几分钟，而不是几小时。这是一个进步，也是时候提交错误报告了。错误报告包含大量剧透信息，因此没有提供链接。
**阶段4：为什么会发生这种情况？**
某些东西导致构建过早结束。这不是OOM killer，内核日志中也没有任何有用的信息。可能是D语言测试向某个进程发送了信号，从而导致make进程终止？作者开始使用bpftrace跟踪发送的信号，编写了以下脚本signals.bt：
```
tracepoint:signal:signal_generate {
printf("%s PID %d (%s) sent signal %d to PID %d\n", comm, pid, args->sig, args->pid);
}
```
并使用sudo bpftrace signals.bt执行。
构建需要一段时间，最终失败。查看跟踪输出，发现一个可疑的进程process.exe正在终止一些东西。
```
process.exe (PID: 2868133) sent signal 15 to PID 711826
```
这看起来很有趣，但作者不知道PID 711826是什么。让我们稍微修改一下脚本，并跟踪接收到的信号。
```
tracepoint:signal:signal_generate {
printf("PID %d (%s) sent signal %d to %d\n", pid, comm, args->sig, args->pid);
}
tracepoint:signal:signal_deliver {
printf("PID %d (%s) received signal %d\n", pid, comm, args->sig);
}
```
工作版本的sbuild使用dumb-init，而新版本使用一个perl编写的init程序。作者修改了当前版本的sbuild，使其使用dumb-init，并跟踪了两个构建：一个使用perl init，一个使用dumb-init。
以下是使用dumb-init构建时观察到的信号：
```
PID 3590011 (process.exe) sent signal 2 to 3590014
PID 3590014 (sleep) received signal 9
PID 3590011 (process.exe) sent signal 15 to 3590063
PID 3590063 (std.process tem) received signal 9
PID 3590011 (process.exe) sent signal 9 to 3590065
PID 3590065 (std.process tem) received signal 9
```
以下是使用perl init构建时观察到的信号：
```
PID 3589274 (process.exe) sent signal 2 to 3589291
PID 3589291 (sleep) received signal 9
PID 3589274 (process.exe) sent signal 15 to 3589338
PID 3589338 (std.process tem) received signal 9
PID 3589274 (process.exe) sent signal 9 to 3589340
PID 3589340 (std.process tem) received signal 9
PID 3589274 (process.exe) sent signal 15 to 3589341
PID 3589274 (process.exe) sent signal 15 to 3589323
PID 3589274 (process.exe) sent signal 15 to 3589320
PID 3589274 (process.exe) sent signal 15 to 3589274
PID 3589274 (process.exe) received signal 9
PID 3589341 (sleep) received signal 9
PID 3589273 (sbuild-usernsex) sent signal 9 to 3589320
PID 3589273 (sbuild-usernsex) sent signal 9 to 3589323
```
使用perl init时，发送了一些额外的SIGTERM信号，这很有帮助。此时，作者确信process.exe值得进一步检查。process.d的源代码显示了一些有趣的内容：
```
1221 @system unittest
1222 {
[...]
1247 auto pid = spawnProcess(["sleep", "10000"],
[...]
1260 // kill the spawned process with SIGINT
1261 // and send its return code
1262 spawn((shared Pid pid) {
1263 auto p = cast() pid;
1264 kill(p, SIGINT);
```
是的，process.d的单元测试中确实有sleep和SIGINT（信号2），就像作者在bpftrace输出中观察到的那样。
是否可以单独研究process.exe的行为，将其与构建分离？确实可以。让我们从失败的构建中获取可执行文件，并尝试在/usr/libexec/sbuild-usernsexec下运行它。
首先，在合适的用户命名空间中准备一个chroot：
```
unshare --map-auto --setuid 0 --setgid 0 mkdir /tmp/rootfs
cd /tmp/rootfs
cat /home/ema/.cache/sbuild/unstable-arm64.tar | unshare --map-auto --setuid 0 --setgid 0 tar xf -
unshare --map-auto --setuid 0 --setgid 0 mkdir /tmp/rootfs/whatever
unshare --map-auto --setuid 0 --setgid 0 cp process.exe /tmp/rootfs/
```
现在可以使用perl init单独运行process.exe，并随意跟踪信号：
```
/usr/libexec/sbuild-usernsexec --pivotroot --nonet u:0:100000:65536 g:0:100000:65536 /tmp/rootfs ema /whatever -- /process.exe
```
可以比较perl init与dumb-init的行为，以毫秒而不是分钟为单位进行比较。
**阶段5：哦，我明白了。**
为什么process.exe在使用perl init时发送更多SIGTERM信号，这是当前的主要问题。作者有一个简单的复现器，因此可以使用strace。
```
sudo strace --user ema --follow-forks -o sbuild-dumb-init.strace ./sbuild-usernsexec-dumb-init --pivotroot --nonet u:0:100000:65536 g:0:100000:65536 /tmp/dumbroot ema /whatever -- /process.exe
```
作者开始比较dumb-init和perl-init的strace输出，特别是查找对kill的不同调用。
以下是process.exe在dumb-init下执行的操作：
```
3593883 kill(-2, SIGTERM) = -1 ESRCH (No such process)
```
没有这样的进程。但在perl-init下：
```
3593777 kill(-2, SIGTERM <unfinished ...>
```
在perl-init下存在该进程！
这是一个带有负PID的kill操作。从kill(2)手册页中可以看出：
如果pid小于-1，则将sig发送到进程组ID为-pid的每个进程。
在bpftrace的输出中看到这个带有负PID的kill操作会非常有用，为什么没有看到呢？使用的跟踪点tracepoint:signal:signal_generate显示信号何时实际发送，而不是调用的系统调用。为了确认这一点，可以跟踪tracepoint:syscalls:sys_enter_kill并查看负PID，例如：
```
PID 312719 (bash) sent signal 2 to -312728
```
此时，显而易见的问题是：为什么在使用dumb-init时没有进程组2？
**阶段6：这是怎么回事？**
作者知道process.exe向进程组ID为2的每个进程发送SIGTERM信号。为了找出这个进程组是什么，作者使用dumb-init生成一个shell，并在/proc下观察PID 1、16和17。使用perl-init时，作者可以看到1、2和17。当运行dumb-init时，在启动程序之前会进行一些fork操作，解释了差异。查看/proc/2/cmdline，可以看到它是bash，也就是在perl-init下运行的程序。在构建包时，也就是dpkg-buildpackage本身。
测试意外地杀死了自己的进程组。
那么，测试中的-2是从哪里来的呢？
```
2363 // Special values for _processID.
2364 enum invalid = -1, terminated = -2;
```
哦，-2用作PID的特殊值，表示“已终止”。后面有一个对kill()的调用：
```
2694 do { s = tryWait(pid); } while (!s.terminated);
[...]
2697 assertThrown!ProcessException(kill(pid));
```
你可能会问，是什么将pid设置为terminated？
以下是tryWait：
```
2568 auto tryWait(Pid pid) @safe
2569 {
2570 import std.typecons : Tuple;
2571 assert(pid !is null, "Called tryWait on a null Pid.");
2572 auto code = pid.performWait(false);
```
以下是performWait：
```
2306 _processID = terminated;
```
读者，解决方法就是不要kill。
PS：对于有兴趣的读者，包含剧透信息的错误报告为#1089007。