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

1c199cf0117b750fe965ffd505530af1.gif

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

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

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

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

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

def hping3(request):
    """
    test latency using hping3
    params in json body:
        dest_ip: str
        dest_port: int
        count: int

    :return: list of floats, each one is a latency, if total count less than ``count``,
        it means some ping get timeout.
    """
    data = request.body
    logger.info(
        "received hping3 request, headers: {}, body: {}".format(request.headers, data)
    )
    data = json.loads(data)
    dest_ip = data.get("dest_ip")
    dest_port = data.get("dest_port")
    count = data.get("count")
    command = "/usr/sbin/hping3 {} -p {} -c {} --syn".format(dest_ip, dest_port, count)

    logger.info("hping3 run command: {}".format(command))
    complete_process = subprocess.run(
        command,
        capture_output=True,
        shell=True,
    )
    returncode = complete_process.returncode
    stdout = complete_process.stdout.decode()
    stderr = complete_process.stderr
    logger.info(
        "result returncode={}, stderr={}, stdout={}".format(returncode, stderr, stdout)
    )

    latency = []
    for line in stdout.split("\n"):
        matched = match_hping_ms.search(line)
        if matched:
            latency.append(float(matched.group(1)))
    return JsonResponse({"latency_ms": latency, "hping3_returncode": returncode})

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

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

一开始有很多错误的怀疑,比如怀疑 hping3 需要 TTY[2] 才能执行,以为 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

vagrant@vagrant:~$ cat pingapp.py
import subprocess

def application(env, start_response):
    start_response('200 OK', [('Content-Type','text/html')])
    p = subprocess.run("hping3 --syn 104.244.42.1 -p 80 -c 3", shell=True, capture_output=True)
    print("return code={}".format(p.returncode))
    return [p.stdout]

然后使用 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 的进程,结束不了。

如同……下面这样:

ffdece652d6354f0cd145a9220bbe76d.png
图1 – 卡住的 hping3

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

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

后面我实在解决不了了,找了(大佬)同事帮忙,花了很多时间,找到以下事实:

  1. hping3 卡住了,发现 SIGTERM 结束不了它,只能 kill -9

  2. 然后发现 uwsgi 进程也有一样的行为了,只能 kill -9 去杀它

  3. hping3 程序被 uwsgi 正常起起来是没问题的,起来之后运行不了

  4. …… 以及中间奇奇怪怪的现象,就不细说了,其实都不重要

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

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

95929f9ee55daa0c7a7a2d8cd0274b71.png

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

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

$ strace hping3 104.244.42.1 -p 80 --syn -c 1
a1e9a74de733fcba94c87185ff28dccd.png

可以看到 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 的代码[3]。发现代码里确实是用这个信号的。

/* use SIGALRM to send packets like ping do */
Signal(SIGALRM, send_packet);

/* binding */
if (ctrlzbind != BIND_NONE) Signal(SIGTSTP, inc_destparm);
Signal(SIGINT, print_statistics);
Signal(SIGTERM, print_statistics);

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

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

root@vagrant:/home/vagrant# cat /proc/4285/status | grep Sig
SigQ:   5/3571
SigPnd: 0000000000000000
SigBlk: fffffffe7ffbfeff
SigIgn: 0000000000000000
SigCgt: 0000000180086002

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

举例:

00000000280b2603 ==> 101000000010110010011000000011
                     | |       | ||  |  ||       |`->  1 = SIGHUP
                     | |       | ||  |  ||       `-->  2 = SIGINT
                     | |       | ||  |  |`----------> 10 = SIGUSR1
                     | |       | ||  |  `-----------> 11 = SIGSEGV
                     | |       | ||  `--------------> 14 = SIGALRM
                     | |       | |`-----------------> 17 = SIGCHLD
                     | |       | `------------------> 18 = SIGCONT
                     | |       `--------------------> 20 = SIGTSTP
                     | `----------------------------> 28 = SIGWINCH
                     `------------------------------> 30 = SIGPWR

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

sigparse () {
    i=0
    # bits="$(printf "16i 2o %X p" "0x$1" | dc)" # variant for busybox
    bits="$(printf "ibase=16; obase=2; %X\n" "0x$1" | bc)"
    while [ -n "$bits" ] ; do
        i="$(expr "$i" + 1)"
        case "$bits" in
            *1) printf " %s(%s)" "$(kill -l "$i")" "$i" ;;
        esac
        bits="${bits%?}"
    done
}

grep "^Sig...:" "/proc/4285/status" | while read a b ; do
        printf "%s%s\n" "$a" "$(sigparse "$b")"
    done # | fmt -t  # uncomment for pretty-printing

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

06784a225cbdf11e39f227115561108e.png

在 manual[4] 中得知:

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

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

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

256ba6a92941a227b9661472d6466f8c.png

果然是的。

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

void uwsgi_setup_thread_req(long core_id, struct wsgi_request *wsgi_req) {
 int i;
 sigset_t smask;


 pthread_setcancelstate(PTHREAD_CANCEL_ENABLE, &i);
 pthread_setcanceltype(PTHREAD_CANCEL_ASYNCHRONOUS, &i);
 pthread_setspecific(uwsgi.tur_key, (void *) wsgi_req);

 if (core_id > 0) {
  // block all signals on new threads
  sigfillset(&smask);
#ifdef UWSGI_DEBUG
  sigdelset(&smask, SIGSEGV);
#endif
  pthread_sigmask(SIG_BLOCK, &smask, NULL);

这段代码是 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% 会卡住。

9f4b96a362cd6e9b7defd3c55d9d2e31.png

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

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

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

Learn some eBPF, xintao!

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

引用链接

[1]

hping3: https://github.com/antirez/hping

[2]

TTY: https://www.kawabangga.com/posts/4515

[3]

代码: https://github.com/antirez/hping/blob/3547c7691742c6eaa31f8402e0ccbb81387c1b99/main.c#L367

[4]

manual: https://man7.org/linux/man-pages/man7/signal.7.html

[5]

fork(2): https://man7.org/linux/man-pages/man2/fork.2.html

[6]

execve(2): https://man7.org/linux/man-pages/man2/execve.2.html

[7]

代码中: https://github.com/unbit/uwsgi/blob/e24fef1fab2a412dce6bd39b4444b2b5775d0d6d/core/loop.c#L77

原文链接:https://www.kawabangga.com/posts/4558

501fdfd9f9d6007a0831ccfac8c6c9f3.gif

b16a1ac15f708a10cc12e21566aac536.png

你可能还喜欢

点击下方图片即可阅读

6330c66a7b64f7bf6ab13becc282f180.png

Opentelemetry 调研实践一(可观测性到底在说什么)

c3723c4d2c67334aeddae0bb2c82d3c9.gif

云原生是一种信仰 🤘

关注公众号

后台回复◉k8s◉获取史上最方便快捷的 Kubernetes 高可用部署工具,只需一条命令,连 ssh 都不需要!

050865676fcc0008c77eb6a13d7dac45.gif

da5d90710454af29525bb25117f66936.gif

点击 "阅读原文" 获取更好的阅读体验!

发现朋友圈变“安静”了吗?

53374cd09ac2254fcf9be26e5e0e6ef2.gif

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值