python文件关闭出故障_499 故障分析——Node 运维惊险排查之旅

最新推荐文章于 2023-02-28 14:40:00 发布

weixin_39636857

最新推荐文章于 2023-02-28 14:40:00 发布

阅读量301

点赞数

文章标签： python文件关闭出故障

本文链接：https://blog.csdn.net/weixin_39636857/article/details/111633120

版权

故障说明

近期，DevOps 团队成员在完善一批老服务监控指标的过程中，意外发现某服务的 access.log 中持续出现一些状态码为 499 的接口请求。与业务方沟通后确认疑似问题接口为关键业务接口，通过获取请求关联的参数，我们随机抽查了 20 条数据， 2 条在数据库中找不到相关记录，其余 18 条数据最终落库成功。基于此我们推断该故障不止会影响用户体验，而且确实会影响到关键业务指标。

分析 Root Cause

HTTP 499

An Nginx specific error code, which means that the client closed the connection before the server answered the request, usually caused by client side timeout.

根据 499 http code 的定义，说明是客户端在服务端请求返回前主动断开了连接，由于是客户端行为，再结合近期频繁的安全事件，初始时我们怀疑有人恶意攻击，故意消耗服务端资源。

是否属于恶意攻击？

我们首先找安全同事核查了 WAF 的配置和日志，但并没有收获。后面跟 ops 同事一起梳理了服务的架构，整理出该接口请求的完整链路：用户 -> WAF -> LB -> Nginx -> pm2 -> nodejs，基于此我们开始分析 499 请求的可能原因。

既然 499 说明用户端主动断开请求，那我们首先要搞清楚的是，用户端断开请求是原因还是结果。

proxyignoreclient_abort on | off;

Determines whether the connection with a proxied server should be closed when a client closes the connection without waiting for a response.

我们修改了 Nginx 配置 proxy_ignore_client_abort on ，这样即便客户端主动关闭了，Nginx 仍然会等到后端服务的返回。配置生效后，马上接口异常调用的状态码由 499 变成 504 ，而后者是我们很熟悉的服务端异常状态码，只可能出现于 Nginx-> pm2-> nodejs 这部分内部链路中。再结合异常日志中的 request_time=60.000 信息，更像是正常请求长时间未得到内部服务正确响应，至此收到外部恶意攻击的可能性就很小了。

客户端为何主动断开？

确定了问题出在内部链路上之后，我们尝试对故障现象做如下假设：

Nginx -> pm2 -> nodejs 接口请求 60s 没得到响应，(用户 | WAF | LB) 中的某环节主动断开上层 server 请求，导致 LB 与 Nginx 的连接被断开，Nginx 响应为 499，从而 LB, WAF 都捕获到 499 状态码。

要让上述假设成立，就必须解释 Nginx -> pm2 -> nodejs 接口请求为何不能响应。在打开 Nginxproxy_ignore_client_abort 后，分析 access.log 中的 504 请求日志。从中随机筛选出几条请求状态码 504 同时 request_time=60.000 的请求日志，然后与 pm2 的 access.log 日志比对，发现后者并没有记录这些请求。范围进一步缩小，难道是 Nginx -> pm2 的网络通信存在问题？

我们选择 504 报错比较多的一台机器，大约每 2 分钟左右会出现一次抓包，开始分析。

# -i lo 抓取回环网卡进出的包， port 8085 pm2端口

sudo tcpdump -i lo host 127.0.0.1 and port 8085 -w xxx.cap

通过 wireshark 打开 cap 文件后，出现有 TCP Retransmission 异常的包，如下图：

我们选取了 Nginx -> pm2 的一个请求进行分析，如下图可以看到从 2019-07-1014:20:31 发送第 1 个 SYN 包后未正常 Ack，调用方重发了 6 次 TCP SYN 包后放弃。

tcpsynretries

Number of times initial SYNs for an active TCP connection attempt will be retransmitted. Should not be higher than 127. Default value is 6, which corresponds to 63seconds till the last retransmission with the current initial RTO of 1second. With this the final timeout for an active TCP connection attempt will happen after 127seconds.

6 次正好是机器的 tcpsynretries 参数，决定了对于一个新建连接，内核要发送多少个 SYN 连接请求才决定放弃。

min(nginx_upstream_timeout, tcp_sync_final_timeout) = min(60s, 127s) = 60s

2019-07-10 14:20:31 + 60s = 2019-07-10 14:21:31

而恰好能在 Nginx access.log 中找到一条对应时间为 2019-07-1014:21:31 的 504 日志。

到这一步，我们已经从现象走出挺远了，离真相也越来越近。TCP SYN 包重传发送失败，可能是机器上的 SYN queue 队列满导致的，我们尝试了调大这个 queue 的 size，问题没有得到一点缓解。另外如果是 SYN queue 满导致的话，随着请求的进行 SYNs packets drop 会不断增加，但间隔一小时后获取 SYNs drop 值，并未发现数量增加。

[root]18:07:02# netstats -s | grep drop

243 ICMP packets dropped because they were out-of-window

149852 SYNs to LISTEN sockets dropped

[root]19:07:22# netstats -s | grep drop

243 ICMP packets dropped because they were out-of-window

149852 SYNs to LISTEN sockets dropped

越接近真相的时候，越容易走弯路。我们又怀疑是由操作系统内核导致的 bug，因为公司绝大部分服务都是运行在 CentOS 上的，而这批服务却跑在 Ubuntu 14.04 上。碰巧我们在 AskUbuntu 上找到了一个相关性很强的 issue: [Application stuck in TCP retransmit](https://askubuntu.com/questions/475700/application-stuck-in-tcp-retransmit)

Linux kernel 3.13 (Ubuntu 14.04) on Virtual Machines 都跟我们的场景一致，我们一度以为找到了 root cause，于是按图索骥调整 MTU，net.ipv4.tcp_sack 参数。很遗憾问题并未得到解决，仍然有 504 请求出现。

不过上面的尝试为我们打开新的思路，要找出 root cause，至少我们需要确认是系统问题还是服务本身的问题。而系统问题其实是非常好验证的，只要我们在同台机器上，尝试 tcp 请求压测，如果 tcp 连接不出问题，就可以确认问题不在系统层。

为此我们设计了一个简单地实验，准备了一套最简单的 golang 的 tcp client / server。在问题机器上启动 golang tcp server，找个客户端运行 tcp client 进行压测。以下是实验方案：

golang client(开5个协程)向 golang server 不断建立连接(连接出错抛error)，写，关闭。

我们跑了接近500w次，未出现 tcp 请求错误

定位 Root Cause

从上面的实验可以看出系统层对 tcp 的处理是没问题的，问题必然出在 pm2 或 nodejs 服务上。其实结合上面 pm2 没有收到请求记录，已经可以判断出问题应该是 pm2 导致的了。我们基于上面的实验方案进行了简单的改造予以证明。

首先我们把上面实验方案中的 golang server 改用 nodejs 实现，重复了一次实验。

golang client(开5个协程)向 nodejs server不断的连接(连接出错抛error)，写，关闭。

我们跑了接近500w次，未出现 tcp 请求错误

符合我们的猜想，nodejs 本身是没问题的，pm2 终于浮出水面。

我们通过 pm2 部署 nodejs
因为 nodejs 跟 python 一样无法使用机器的多核能力，所以常规的部署方式是通过进程管理器去启动多个 nodejs 进程，而 pm2 通常是 nodejs 服务的进程管理器首选。

golang client(开5个协程)向 pm2 server不断的连接(连接出错抛error)，写，关闭。

我们跑了不到2k次，就出现了报错

已经很明朗了，这个锅 pm2 是逃不掉了。

问题修复

因为我们团队对 nodejs 的了解有限，首先想到的是从社区寻找解决方案，毕竟 pm2 是近 3w Start 的项目。很快我们在 github pm2 项目的 issues 讨论中找到答案。果真有人与我们遇到相同的问题，issue #1484 并提供了 workaround 方案。

我们使用该方案，在 Nginx 上增加了 keepalive 64，目前服务已经运行近 1 周，未再出现 504 报错。后续我们将该问题转交给公司的 nodejs 开发同事，希望他们能给出彻底解决故障的方案。