概要

从nginx的499着手，分析整个过程中是怎么产生499行为的，以及各种往返网络包出现的原因。说说我通过这个499问题一步一步分析的整个过程，作为一个web服务端程序员，但很有意思。

故事背景

前几天同组的应届生同事在排查线上问题的时候突然问我，这个499的错误码是什么？我轻描淡写的回复了就是客户端设置的超时时间到了，nginx自己记录的内部错误码。这样草草打发之后，我的内心久久不能平复，499的背后nginx和客户端以及upstream到底发什么了什么，不得而知。事实上，当时我还认为的这样一个事实：

即使client断开了，最后nginx还是会把返回的网络包发过来，站在网络流量资源的角度来看，超不超时貌似没有区别。

接着我去查了一下nginx对499对定义，只说明了这是client关闭连接的code，没有其他更深入的信息。

/
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

为了搞清楚我的猜想是正确的，我做了一系列实验，查看了相关源码，最后才知道这个事实是多么的错误。

实验

os：mac
服务：golang+nginx+(php)fpm
调用：golang作为client，发起http调用，设置1秒超时，php对应接口sleep 3秒之后响应，nginx作为反向代理（和fpm使用tcp socket通信）

代码：

// main.go
package main
import (
"net/http"
"time"
)

func main() {
c := http.DefaultClient
c.Timeout = 1 * time.Second
c.Get("http://localhost:6100/index.php")
}

// inedx.go
<?php
sleep(3);
echo "i sleep 3 seconds";

6100 端口是 nginx 代理的端口，运行 main.go，果然在 access.go 里面出现了一条 499 的日志。

127.0.0.1 - - [29/Dec/2019:14:14:43 +0800] "GET /index.php HTTP/1.1" 499 0 "-" "Go-http-client/1.1"
看看这背后究竟发生了什么？既然我在本地运行，那么直接上 wiresharks 抓包看看就好了。

整个过程会用到2个tcp连接，4个端口

1. [26-27] 14:14:42 client第一次握手被nginx rst

2. [28-31] client和nginx三次握手

3. [32-33] client发送http，nginx确认收到

4. [34-37] nginx和fpm三次握手

5. [38-39] nginx发送请求到fpm（fcgi协议）

6. [44,45,48,49] 因为client设置了1秒超时，这里刚好1秒过去，时间是14:14:43，断开链接，这4个包是一次完整的四次挥手

7. [46, 47] 在nginx收到client断开，接着给fpm发送了断开，同时fpm响应了ack，nginx进入finwait-2状态，这里通过 netstat 可以确认

8. [52-55] 2秒之后14:14:45，fpm处理完逻辑返回，写回数据到 nginx，同时响应 fin+ack，这里nginx给了两次 RST

抓包到这里我们可以得到如下结论：

1. nginx接受client的get请求完之后，会接着开始转发到upstream
2. client断开之后，nginx马上同意关闭tcp连接
3. 499的日志记录时间就是tcp断开的时间
   让人费解的是最后两个RST是怎么产生的，整理这篇文章的时候我已经不记得当初为什么又这个疑问了，这里假设我们还是对这个问题很好奇，不然接下来的文字好像没法继续写了。

实验分析

通过46,47两个包我们知道了nginx的61394端口tcp处理finwait-2的状态，于是我找来了【相关文档 RFC793】对tcp状态转化的定义：

在FINWAIT-2的状态没有snd rst的相关说明，这个图只是正常流程的tcp状态扭转说明，那接着向下看。不过有经验的同学应该已经猜到大概是因为在FINWAIT-2的状态下收到数据，主动关闭的一方会直接发送RST，我很想找到某个官方文档上有相关的定论，这样这个问题就到此为止了。运气很差，翻了几篇RFC文档没有找到，那我只能自己从TCP源码找找线索了。

// linux/net/ipv4/tcp_input.c#L6129
/*
* This function implements the receiving procedure of RFC 793 for
* all states except ESTABLISHED and TIME_WAIT.
* It's called from both tcp_v4_rcv and tcp_v6_rcv and should be
* address independent.
*/
int tcp_rcv_state_process(struct sock *sk, struct sk_buff *skb)
{
    struct tcp_sock *tp = tcp_sk(sk);
    struct inet_connection_sock *icsk = inet_csk(sk);
    const struct tcphdr *th = tcp_hdr(skb);
    ...
    switch (sk->sk_state) {
        ...
        case TCP_FIN_WAIT2:
        /* RFC 793 says to queue data in these states,
        * RFC 1122 says we MUST send a reset.
        * BSD 4.4 also does reset.
        */
        if (sk->sk_shutdown & RCV_SHUTDOWN) {
            if (TCP_SKB_CB(skb)->end_seq != TCP_SKB_CB(skb)->seq &&
            after(TCP_SKB_CB(skb)->end_seq - th->fin, tp->rcv_nxt)) {
                NET_INC_STATS(sock_net(sk), LINUX_MIB_TCPABORTONDATA);
                tcp_reset(sk);
                return 1;
            }
        }

        ...
    }
    ...
}

这是tcp收到数据包的处理函数，省略了大部分代码（因为读起来很费劲且不是这个问题的关键点），找到了在TCP_FIN_WAIT2状态下唯一一处发送RST的代码，这段代码两个if条件大概是：

1. 当前sk(tcp socket)关闭了读取通道(RCV_SHUTDOWN)

2. 函数收到的数据包有内容且检测seq序列号是正确的(可能某个很早包在网络世界中漫游到现在才收到，这种情况要走其他逻辑处理)

看来事情已经很简单了，我只要找到 sk->sk_shutdown |= RCV_SHUTDOWN 这行代码，我的问题就可以得到解决了。在接近真相的时候我们往往会掉入另外一个坑，是的，只知道了一行不相关的代码。

很苦恼，我深信RST就是通过这行代码发送出去的，于是我用strace(mac下使用dtruss)把这几个关键进程的系统调用打了出来。

# golang 部分
## 过期主动断开tcp
1541/0x1a35ce3: 23140 6 2 close(0x5) = 0 0

# nginx 部分
90320/0x1a30d81: 13045 34 21 write(0xA, "2019/12/29 16:07:27 [info] 90320#0: *62 kevent() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 127.0.0.1, server: _, request: .GET /index.php HTTP/1.1., upstream: .fastcg", 0x12C) = 300 0

## close对upstram的socket
90320/0x1a30d81: 13267 50 37 close(0x4) = 0 0

## nginx 499日志
write(0xB, "127.0.0.1 - - [29/Dec/2019:16:07:27 +0800] .GET /index.php HTTP/1.1. 499 0 .-. .Go-http-client/1.1...", 0x64) = 100 0

## close client socket
90320/0x1a30d81: 13773 39 30 close(0x3) = 0 0

# fpm部分
## 处理完成之后http响应
78089/0x1a2b512: 17360 101 77 write(0x3, ".01.06.", 0x70) = 112 0
## shutdown tcp
78089/0x1a2b512: 17410 397 9 shutdown(0x3, 0x1, 0x0) = -1 Err#57

这部分其实系统调用都是关于tcp连接断开的：

1. go client 调用超时之后直接 close socket
2. nginx 捕获到这个 close io，响应的进行 socket 关闭
   3. 先关闭对 upstream 的 socket
   4. 然后关闭对 client 的 socket
3. fpm 超时之后继续处理逻辑，完成之后进行write输出数据，输出之后调用 shutdown 关闭 socket

看到shutdown函数，我迅速翻开了垫在电脑下的TCP/IP卷一，TCP/IP卷一如下描述TCP半关闭：

tcp的半关闭操作是指仅关闭数据流的一个传输方向，而两个半关闭操作合在一起就能够关闭整个连接。为了实现这一特性，API为程序提供一种表达方式，使用 shutdown() 函数来代替基本的 close() 函数。

php脚本处理完之后，马上会执行shutdown来关闭socket的写入通道，很合理，毕竟逻辑已经处理完了，不需要再向nginx返回数据了。注意，这里通过系统调用可以看到参数和返回值 shutdown(0x3, 0x1, 0x0) Err#57

#define SHUT_RD 0 /* shutdown for reading */
#define SHUT_WR 1 /* shutdown for writing */
#define SHUT_RDWR 2 /* shutdown for reading and writing */

马上联想到想到前面我通过 sk->sk_shutdown |= RCV_SHUTDOWN 来搜索线索，对于位运算太久没用已经麻木了，读写通道肯定是读和写两个位的组合，我打开了 linux 的源码，在我 14 年的mac本上有点卡，迅速搜索关键词，终于真相了

//linux/include/net/sock.h
#define SHUTDOWN_MASK 3
#define RCV_SHUTDOWN 1
#define SEND_SHUTDOWN 2

//linux/net/ipv4/tcp.c
void tcp_close(struct sock *sk, long timeout)
{
    struct sk_buff *skb;
    int data_was_unread = 0;
    int state;
    lock_sock(sk);
    sk->sk_shutdown = SHUTDOWN_MASK;
    ...
}

执行close函数，当socket的引用计数位0的时候，会真正去断开连接，这个系统调用背后执行了 tcp_close 函数。关于close可以在百度上看看和shutdown有哪些细节上的区别，这里就不细说了。

通过以上分析，第一个RST产生的原因就比较明确了，处于finwait-2且关闭了读写通道，收到数据包的时候会直接产生RST。同时会直接丢弃到这个TCP连接，不会进入TIME_WAIT了。

那么，第二个RST怎么产生的，为什么fpm发送一个fin包会被再次RST，熟悉网络编程的人应该已经知道答案了，在nginx上这个连接已经丢弃了，所以直接予以RST。其实写这段文字，是因为我在验证这个逻辑的时候掉入了一个有意思的陷阱。

一个陷阱

回过头看看fpm shutdown系统调用的错误码Err#57，shutdown可能产生的错误码文档上已经列出来了。

我切换到linux项目，搜索ENOTCONN（看起来当前场景的错误码），结果让人大失所望

#define ENOTCONN 107 /* Transport endpoint is not connected */
#define ENOTSOCK 88 /* Socket operation on non-socket */

后来，我花了很久才意识到，我用mac本在测试代码，而我打开的内核代码是linux的，所以我很快在freebsd的代码找到了我想要的答案

#define ENOTCONN 57 /* Socket is not connected */

一点思考

整个过程并没有文章上这么顺利，很多知识点上我都看到了自己的欠缺，深感网络编程的不易。在我本地调试的过程中，我还进行了下面的实验：

1. 重新编译nginx，把所有debug日志打开，这样整个过程会非常清晰。
2. 去掉nginx代理，直接请求后端go服务或者tomcat超时
3. 在超时期间，模拟upstream断电，nginx的FINWAIT-2会怎么处理

限于篇幅，这篇文章就不再展开了，关于499的了解到这一步应该已经足够深入了。

参考

TCP协议超时详解

TCP 之 FIN_WAIT_2状态处理流程

tcp_rcv_state_process 源码

RFC793

shutdown(3) - Linux man page

freebad errno

TCP/IP详解-卷一-TCP连接管理

最后欢迎大家关注我的公众号，我给自己定个每个目标达成之后都会有实体书赠送抽奖活动。