Debug 一个在 uWSGI 下使用 subprocess 卡住的问题

今天花了很长的时间在排查一个诡异的问题，值得记录一下。

本来是想写一个 HTTP 的服务，你告诉这个 HTTP 服务一个 IP 地址和端口，这个 HTTP 服务就可以返回通过 TCP 访问这个 IP 端口的延迟。因为我们每次做 chaos 注入的时候都要测试一下注入延迟成功了没有，有了这个服务，这个测试就可以自动化。

其实很简单，收到请求之后用 TCP ping 几次拿到延迟，然后返回就可以了。

之前测量 TCP 的延迟使用的都是 hping3，Redis 的作者 antirez 写的。然后就想到用这个工具来做测试好了。

搜索了一下发现没有 Python 的 binding，所以打算粗暴一些，直接在 HTTP 服务里面 fork 出来一个进程做测试，然后去处理 stdout，grep 出来延迟的数据。很快就写好了，代码大体如下：

很简单的一段代码，收到请求，调用命令，返回结果。框架使用的是 Django，在本地测试一切正常，然后发布到 staging, 噩梦开始了……

在 staging 环境中，测试的时候发现，HTTP 请求发过去永远收不到回应，最后会得到一个 504 Gateway Timeout 的结果。去容器（应用运行在一个容器里面）看，发现 hping3 进程一直没有结束，像是卡住了。

一开始有很多错误的怀疑，比如怀疑 hping3 需要 TTY 才能执行，以为 hping3 需要使用绝对路径等…… 但是想想同样的代码在本地可以运行正常，就应该不是这些原因。一个验证就是，我去应用运行的环境中开一个 Python 的 REPL 执行这段代码，是能正常得到结果的。在应用运行的环境直接运行 hping3 命令，也是没有问题的。

然后怀疑 hping3 没有足够的权限来运行，因为 hping3 发送的是 raw TCP/IP 包，需要 CAP_NET_RAW 才能执行。去容器里面检查了一下，发现这个 capability 也是有的。

到这里，其实已经花费了很多时间了，得到的事实有：

1. 容器里面执行 hping3 是完全没有问题的，权限是足够的
2. 直接使用 Python3 的 REPL 执行这段代码也是没有问题，代码逻辑是对的

到这里你能猜到问题出在哪里了吗？

其实还有一个运行环境没有提到，就是 uWSGI. 这个 Python 写的服务是作为 WSGI 应用跑在 uWSGI 里面的。不知道和 uWSGI 有没有关系（直觉告诉我是有的，比直觉更厉害的同事也告诉是有关系的）。于是我打算直接使用 python manage.py runserver 在容器里面跑起来试试……

一切正常了。

所以 python 直接跑应用没问题，用 uWSGI 运行就有问题。现在问题锁定在 uWSGI 上面了。为了复现这个问题，我写了一个最小的测试用例。

首先需要一个文件，叫做 pingapp.py。

然后使用 uWSGI 运行这个程序：uwsgi --http-socket :9090 --wsgi-file pingapp.py --threads=4.

uWSGI 的版本是 2.0.20，Python 的版本是 3.7.5, 但其实这不重要。

最后，访问这个程序，即 curl localhost:9090.

如果是 uWSGI 的问题的话，我们期望这里已经可以复现问题了，即 curl 命令会卡在这里，然后进程( ps -ef )里面出现一个 hping3 的进程，结束不了。

如同……下面这样：

但现实是……这个程序一点问题没有，运行地丝般顺滑。

这就见鬼了，直接没了思路。我的应用和这个最小的复现代码根本没什么（太大的）区别啊！我又没有用一些奇奇怪怪的 lib。

后面我实在解决不了了，找了（大佬）同事帮忙，花了很多时间，找到以下事实：

1. hping3 卡住了，发现 SIGTERM 结束不了它，只能 kill -9
2. 然后发现 uwsgi 进程也有一样的行为了，只能 kill -9 去杀它
3. hping3 程序被 uwsgi 正常起起来是没问题的，起来之后运行不了
4. …… 以及中间奇奇怪怪的现象，就不细说了，其实都不重要

最后虽然也找到了根因，但是走得路太弯了。本文从这里开始，就以事后诸葛亮的视角，看看有了上面的信息，我们怎么从正确的思路一步一步找到问题。

首先，同样的环境，在 shell 里面可以正常执行 hping3 但是 uWSGI 里面却不可以，既然 uWSGI 能正常开 hping3 进程，我们就可以看看这个进程到底卡在了哪里？

通过 strace 可以发现它一直在 poll 4 这个 fd，然后查看这个 fd，发现它是一个正常的 socket，应该就是 ping tcp 端口使用的那个 socket.

然后，我们应该去看一下，正常的 hping3 的 trace 是什么样子的。

strace hping3 104.244.42.1 -p 80 --syn -c 1

可以看到 poll 附近很神奇，下面突然就开始 write 到 stdout 内容了。不知道怎么结束的。

但是往上看，有一段代码获取了当前的 pid，然后给自己发送了 SIGALRM。再往前，发现注册了 SIGALRM 的 handler.

SIGALRM 是什么呢？

SIGALRM is an asynchronous signal. The SIGALRM signal is raised when a time interval specified in a call to the alarm or alarmd function expires.

看起来是用来做异步的。

搜索了一下 hping3 的代码。发现代码里确实是用这个信号的。

 

那么我们的 uWSGI 下的异常 hping3 是否是因为没有收到这个 SIGALRM 而一直在傻 poll 呢？

在上面的 图1 中，卡住的 hping3 pid 是 4285，我们看下这个进程能否处理信号：

这里可以发现 SigBlk 不是全 0 的，说明有 signal 被 block 了。SigBlk 是个 64 个 bit 组成的 bitmask，每一位代表一个 signal 是否被 block，1 是 block，0 是没有 block。从右到左分别表示 1-64 号信号。

举例：

可以使用下面这段脚本去 parse 到底哪些信号被 block 了：

可以看到，hping3 需要的 14 号信号正好被 block 了。

在 manual 中得知：

A child created via fork(2) inherits a copy of its parent’s signal mask; the signal mask is preserved across execve(2).

所以说，我们正常的 hping3 可以收到 signal，但是 uWSGI 里面 fork 出来的进程就不可以，可能是 hping3 从 uWSGI 里面继承了 signal mask，导致它也去 block 14 这个 signal 了。

我们可以去看下 uWSGI 里面是否也是 block 了这个 signal 的：

果然是的。

在代码中发现，里面只有 core_id = 0 的 thread 是处理信号的，其余的 thread block 了所有的信号。

这段代码是 core_id 如果大于0，那么 block 所有的信号，如果不大于 0，就处理信号。

所以到现在也就明白我写的那个最小的 case 为什么不能复现了：我使用了默认配置，只有一个 thread，core_id =0，它永远可以处理信号。而生产环境开了 64 个 thread，只有 1/64 的几率能够处理信号从而让应用正确返回。

我们可以重新验证一下，开 2 个 thread，预期是它会有 50% 的几率卡住：

uwsgi --http-socket :9090 --wsgi-file pingapp.py --threads=2

果然是，50% 能得到结果，50% 会卡住。

 

到这里就真相大白了。至于修改呢，我打算直接用 socket.connect 来测量 tcp 的连接时间。因为 TCP 是 3 次握手的，但是对于客户端来说基本上只花费了一个 RTT 的时间。测试下来，这样得到的时间和 hping3 也是一致的。

 

另外这个故事告诉我们，uWSGI 下 fork 出来的子进程最好都默认信号不工作，虽然 core_id =0 是可以处理信号的，但是这个作为 uWSGI 本身回应信号的设计就可以。发现 uWSGI 的代码中还有很多别的地方调用了 sigprocmask(2)，可能还有其他屏蔽信号的地方。

 

有一位智者同事曾经跟我说过这么一句话：

Learn some eBPF, xintao!

看来是时候认认真真学一学 eBPF 啦。

 

---