Nginx神奇的499竟然不在HTTP响应码标准内？快来了解一下！

淡淡的烟草味﹌ 2024-03-03 03:55 62阅读 0赞

### 1 前言 ###

高性能的HTTP和反向代理服务器，Nginx用来：

*  搭建Web Server
 *  作负载均衡
 *  供配置的日志字段丰富，从各类HTTP头部到内部性能数据都有

Nginx的访问日志中，存在499状态码的日志。但常见4xx状态码只有400、401、403、404等，499并未在HTTP RFC文档。这499错误日志，在流量较大场景下，特别是面向Internet的Web站点场景下还是很常见 。

### 2 案例 ###

某客户反馈：Nginx服务器连续几天记录较多499错误日志，之后几天趋零，再回升，整体状况不定。

经营的To C产品，跟手机端App协同。App会定时把消息上传到微信消息网关，后者再把这些消息推送到该客户的服务端（在公有云上）做业务处理，整体消息量约每日三十万条。对消息网关来说，这服务端就是一个Web回调接口：

![2b00af379b614a3ead96084a3a009ce7.png][]

499日志趋势：

![image-20230914091509298][]

由于大量499日志存在，客户非常担心业务已受影响，如终端消费者是否经常上传数据失败？499状态码本身意味着啥呢？查它在Nginx的 [官方定义][Link 1]：

> NGX\_HTTP\_CLIENT\_CLOSED\_REQUEST | 499

client closed request（客户端关闭了请求）？说了跟没说没区别。啥引起“客户端关闭请求”？

###### 解决问题办法，可能不在问题自身所处层面 ######

应用层日志记录的只是表象。更深层次原因可能在更底层，如传输层或网络层。搞清499：

*  不仅是理解这个499码底层含义
 *  而且通过排查，掌握一套 **对HTTP返回码进行网络分析的方法**。对维护好Nginx以及其他Web服务都有助

来抓包分析HTTP返回码真正含义。

### 3 锚定到网络层 ###

软件文档已无法查清根因，所以要下沉到网络层排查。如你处理应用层故障，如HTTP异常返回码（4xx和5xx系列），也遇到应用层找不到答案，就抓包分析。

> 后文
> 
>  *  “客户端”指微信消息网关
>  *  “服务端”指这客户在公有云的服务器

在 **服务端** 使用tcpdump工具抓包，Wireshark打开抓包文件。从抓包文件中一般寻找可疑报文。这次抓包有不少RST报文，过滤出典型的带RST报文的TCP流：

![ecc679f75a084f4888ed80a651d9dffe.png][]

> 抓包文件可关注【JavaEdge】联系本人领取。

结尾处RST。这TCP流一定跟499日志有关系吗？得益于TCP/IP精妙分层设计，应用层只需通过系统调用，就可像使用文件IO那样使用网络IO，具体的网络细节都由内核处理。可由此也带来问题： 应用层视角无法“看到”具体的网络报文。

![bfc0652044fb432da0e17789e16f08a1.png][]

需根据关键信息确定应用层日志跟网络报文的对应关系。如这里，可确认上面这带有RST的TCP流，就是日志中记录的一条499日志记录。因为：

*  **客户端IP**：日志中的remote IP跟抓包文件里面的IP符合
 *  **时间戳**：日志的时间戳也跟这个TCP流的时间吻合
 *  **应用层请求**：日志里的HTTP URL路径和这个TCP流里的URL相同

> 04也是类似方式找到应用日志跟报文对应关系。

真实抓包分析场景中，“如何把应用层问题跟网络层抓包关联”，始终是关键环节。也是令人困扰的关键技术障碍。所以这里方法可参考，再处理这种关键环节，也可根据上面提到的三维即IP、时间戳、应用层请求（包括URL和header），把应用层问题锚定到网络层数据包。

既然确定这个流就代表一次499事件，好好分析报文。

### 4 解密TCP流 ###

TCP流示意图红框部分是重点。

![image-20230914101947340][]

报文1~3，表示TCP握手成功。

报文4（客户端发出），表示客户端向服务器发报文，报文里只包含HTTP header，其声明该请求为POST方法，但不含POST body。正常，因为HTTP协议规定数据先后顺序：先header（包含method、URL、headers），后body。所以，既然method和URL单独位于一个报文，按顺序body就在后续的报文。

报文5（服务端发出），确认报文：我（服务端）确认收到了你（客户端）发过来的报文4。

报文6（客户端发出），距上一报文2s。这报文被Wireshark标红，注释TCP Previous segment not captured：它之前的TCP报文段没被抓到。

#### 之前的TCP报文”是啥？ ####

就是按TCP序列号顺序，排在当前报文之前的报文。先关注右边红框FIN标志位，说明这是客户端主动关闭连接的报文。

目前报文情况：

![image-20230914103706786][]

明明HTTP POST请求的body（也称HTTP载荷）还没发过来，客户端就要关闭连接？好比朋友说：“我有个事情要你帮忙，嗯，拜~”，你刚听到上半句他的求助意向，还没听到这忙是个啥，他就跟你说再见。可能暂时看不出问题，先放放。

![4f05dda118df4fbcb66b6d7d914b9bac.png][]

报文7（服务端发出）。服务器收到FIN+ACK报文（6号报文），但发现序列号不是它期待的309，而是777，于是服务器TCP协议栈判断：有一个长度为777-309=468的TCP段（TCP segment）丢失了。

按TCP约定，这时服务端只可确认其收到的字节的最后位置，在这里就是上次（报文5）的ACK位置。形式上，报文7就成了一个DupAck（重复确认）。

当客户端收到DupAck时，它就要长个心眼：“情况有点微妙，如果凑满3个DupAck可能有丢包”。

> 如凑满3个DupAck就重传的机制，被称为快速重传机制，12深入学习过。

报文4的TCP信息：

![bf9fd6f986284be6ad75fd4fde1c3c94.png][]

按TCP设计，客户端将发送的下一个报文的序列号（309）= 本次序列号（1） + 本次数据长度（308），即Next sequence number。

报文8（客户端发出），16s之久，客户端 **重传** 了这个报文，包含POST body，长度 **468** 字节。就跟777-309=468对应。

明明这468字节的报文是第一次出现，怎么算重传？因为，这个抓包文件是在服务端生成，所以它的视角无法看到多次传送同样这个报文的现象。但我判断，客户端抓包，一定可看到这个468字节的报文被试图传送多次。

![3a048761fc6647eb9de7650fca19342d.png][]

服务端视角判断，一开始这报文应该是走丢，没到达服务端，所以没在这服务端抓包文件里。又因为过16s才到，很可能不是单纯一次重传，而是多次重传后才到达。因此确实属重传。

报文9，服务端对这POST body的数据包回复确认报文。

报文10，服务端发HTTP 400的响应报文给消息网关。这信息并没有被Wireshark直接按HTTP格式进行展示，但因HTTP是文本编码，所以可鼠标选中Transmission Control Protcol部分，在底下文本栏直接看到HTTP 400这段文本：

![2430bcf62d4a49b582d79b262530755d.png][]

这HTTP 400报文也带FIN标志位，即服务端操作系统“图省事”，把应用层的应答数据（HTTP 400），跟os对TCP连接关闭的控制报文（这个FIN），合并在同一个报文。03提到的搭顺风车（Piggybacking），提升网络利用率。

这阶段报文：

![1a396589691a4ca6b18487eb43fa4f23.png][]

从这些报文顺序来看，确实有问题：

*  服务端先收到HTTP header报文，没收到期望的HTTP body报文，而是收到FIN报文（客户端试图关闭连接）。HTTP请求还没发到服务端，服务端回复HTTP响应更无从谈起，客户端就发FIN不符常理（
 *  服务端回复HTTP 400，并发送FIN关闭这连接
 *  客户端回复RST彻底关闭这连接
    
    **客户端先发送了FIN，之后才发POST body。** 全部过程：

![0d062bbefec643c1b90d40917f740285.png][]

**服务端还没回复数据而客户端已经要关闭连接**，按499官方定义，这种行为被Nginx判定499状态：

*  对内表现为记录499日志
 *  对外表现为回复HTTP 400给消息网关

所以，在服务端的Nginx大量499日志条目；在消息网关那头，如果它也做Web日志，就是400报错。

### 5 从现象到本质 ###

为什么客户端先发送FIN，然后才发送POST body？

回到Wireshark窗口，再关注6号报文：

![b8312ac513174c4fa6168eef812c6e43.png][]

离上个报文相差了2s。

往前看4号报文：

![4b9212f1f687443e8c28780c82d5dc1e.png][]

离3号报文相差3s。加起来，6号报文离TCP握手完成，正好隔 **5s整**。

一般出现这种整数，就越可疑，因为如果是系统或网络错乱导致，时间分布应 **随机**，不可能卡在整数时间。经验看， **这和人为设置有关**。于是客户仔细查看微信网关使用文档，发现5s超时设置。即若一个HTTP事务无法在5s内完成，就关闭这连接。

![145df42ebff744d580a28df40218af2a.png][]

#### 啥叫无法完成？ ####

在这抓包里即：HTTP header报文发过去了，但HTTP body报文没一起过去（网络原因导致）。而由于初始阶段报文少， **无法凑齐3个DupAck**，所以快速重传没有启动，只好依赖超时重传（12 讲），且这多次超时重传也失败，服务端只好持续等待这丢失的报文。5s后，客户端没收到服务端响应，就主动关闭这次连接（可以下次再试，这次就不继续干等）。

即该场景里Nginx 499错误日志主因：

*  消息网关—>服务器 方向上的一个TCP包丢失（案例里是HTTP POST body报文），引起服务端空闲等待
 *  消息网关有5s超时设置，即连接达到5s，消息网关就发FIN关闭连接

逻辑链：

*  要解决499报错的问题，就需要解决5s超时
 *  要解决5s超时，就要解决丢包
 *  要解决丢包，就要改善网络链路质量

最根本解决方案，如何确保客户端到服务端的 **网络连接** 可靠稳定，使类似的报文延迟现象降到最低。只要不丢包不延迟，HTTP事务就能在5s内完成，消息网关就不会启动5s超时断开连接机制。

跟客户还有网关工程师配合，确实发现网关到公有云的一条链路有问题。更换为另外一条链路后，丢包率大幅降低，问题极大改善。虽然还是有极小比例的错误日志（约万分之一），但对客户已在可接受范围。

因为丢包，客户端FIN报文跟HTTP POST body报文一样，也可能丢失。不过，无论这FIN是否被服务端及时收到，这次HTTP事务本身也已在客户端记为失败。

#### 链路丢包这种问题挺明显，为啥没及时发现？ ####

*  虽然对主要链路的整体状况有细致的监控，但这里的网关到客户的公有云服务属于“点到点”的链接，本身也属于客户自身的业务，公有云难以对这种情况做监控，理想情况是客户自己来实现监控。
 *  客户的消息量很大，哪怕整体失败比例不高，但乘以绝对的消息量，产生的错误的绝对数也就比较可观了。

至于Nginx为何“创造”499状态码， [Nginx源码][Nginx] 注释写得清楚。并非标新立异，而确实是为了弥补标准HTTP协议不足：

/*
     * HTTP does not define the code for the case when a client closed
     * the connection while we are processing its request so we introduce
     * own code to log such situation when a client has closed the connection
     * before we even try to send the HTTP header to it
     */
    #define NGX_HTTP_CLIENT_CLOSED_REQUEST     499

### 6 总结 ###

**Nginx 499是Nginx定义状态码，不是RFC中定义HTTP状态码**。表示“Nginx收到完整的HTTP request前（或者已经接收到完整的request但还没来得及发送HTTP response前），客户端试图关闭TCP连接”这种反常情况。

**超时时间跟499报错数量也有直接关系**。如果我们有办法延长消息网关的超时时间，比如从5秒改为50秒，那么客户端就有比较充足的时间去等待丢失的报文被成功重传，从而在50秒内完成HTTP事务，499日志也会少很多。

**关注网络延迟对通信的影响**。比如客户端发出的两个报文（报文3和报文4）间隔了3秒钟，这在网络通信中是个非常大的延迟。而造成这么大延迟的原因，会有两种可能：

*  消息网关端本身是在握手后隔了3秒才发送了这个报文，属 **应用层问题**
 *  消息网关在握手后立刻发送了这个报文，但在公网上丢失了，微信消息网关就根据“超时重传”的机制重新发了这个报文，并于3秒后到达。属 **网络链路问题**。

由于上面的抓包是在服务端做的，所以未到达服务器的包自然也不可能抓到，也就是无法确定是具体哪一种原因（客户端应用层问题或网络链路问题）导致，但这并不影响结论。

公网丢包现象不可能完全消失。千分之一左右公网丢包率是正常范围。由于：

*  客户发送量较大（主因）
 *  微信消息网关设置5s超时相对较短（次要原因）

问题就会在这个案例中被集中暴露。

设置更长超时阈值（如50s）能解决？出错率会降低不少，但新问题：

*  消息网关会有更多的资源消耗（内存、TCP源端口、计算能力等）
 *  消息网关处理事务的平均耗时会增加

所以，5s是权衡后的合适方案。

排查的方法论，对更广泛的应用层报错日志的排查，推荐：

*  先查应用文档，初步确定问题性质，大体确定排查方向
 *  对比应用日志和抓取的报文，在传输层和网络层寻找可疑报文。这步，可采用比对策略找到可疑报文：
    
     *  日志中的IP跟报文中的IP对应
     *  日志和报文的时间戳对应
     *  应用层请求信息和报文信息对应
 *  结合协议规范和报文现象，推导出根因

### FAQ ###

*  第7个报文是DupAck，为什么没触发快速重传？
 *  消息网关那头的应用日志应该不是499，那会是啥样日志？
    
    > 本文由博客一文多发平台 [OpenWrite][] 发布！

[2b00af379b614a3ead96084a3a009ce7.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/2855c25e281e4ebba4527a722ef317c6.png
[image-20230914091509298]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/b3074fbd7d4744bb8c8732a90e5ea14c.png
[Link 1]: https://www.Nginx.com/resources/wiki/extending/api/http
[ecc679f75a084f4888ed80a651d9dffe.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/5c0902cc353d4c68a62a24dd2705c503.png
[bfc0652044fb432da0e17789e16f08a1.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/458ef0e266b3447583528527963ef29e.png
[image-20230914101947340]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/e454095981d24162b5cc6a92fae1cc8a.png
[image-20230914103706786]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/1d37d5f5c75142d084ae353ae227a043.png
[4f05dda118df4fbcb66b6d7d914b9bac.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/5d616998606849b19bb01cc55449f0d7.png
[bf9fd6f986284be6ad75fd4fde1c3c94.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/9f26be8de32f4498afff93039e594253.png
[3a048761fc6647eb9de7650fca19342d.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/015332e93cee473bba777c2fc5f94f16.png
[2430bcf62d4a49b582d79b262530755d.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/115dd4dfd1564a02b363b6da022d9bd8.png
[1a396589691a4ca6b18487eb43fa4f23.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/4bd9b47c52b64718a4d89eb97d4d02f1.png
[0d062bbefec643c1b90d40917f740285.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/1cc55a64744343ab8ff3dabfcc4fabac.png
[b8312ac513174c4fa6168eef812c6e43.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/858bc4f0401f4813951adb0a10df6c9e.png
[4b9212f1f687443e8c28780c82d5dc1e.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/9a3859eb764d4db0bdedec83945303a3.png
[145df42ebff744d580a28df40218af2a.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/03/6bb6336dc41348dca77634fbe42cc510.png
[Nginx]: https://github.com/Nginx/Nginx/blob/a6cb8210905f35977276cb3861184e4dad99cc2a/src/http/ngx_http_request.h
[OpenWrite]: https://openwrite.cn?from=article_bottom