记一次Nginx产生RST的研究
背景
在Linux EC2上部署了Nginx服务,前面加了一个AWS NLB,使用Route 53 Health Checker来对NLB进行健康检查,其原理是模拟发送HTTPS GET请求。NLB提供了客户端和服务端产生的RST指标,指标显示Linux产生了很多RST。
初步分析
虽然产生了RST,但不代表真的有影响。先从客户端,也就是Route53 Health Checker入手,发现所有的检查结果都是成功的,即可以获取到200状态码,那么看来虽然服务端产生了RST,但对客户端的访问没有影响。
抓包分析
在nginx上查看访问日志一切请求都是200的响应,这也印证了对客户端的访问没有影响,那么大概率是发送HTTP响应之后,关闭连接的时候发送的RST。 找了另一个Linux使用curl访问nginx,并在nginx抓包看一下交互过程。
curl https://10.0.0.125 -vk ----> nginx没有发送RST
这就奇怪了,再次抓包,特别关注Route53发来的请求,发现关闭连接的时候Nginx先发送了FIN,之后又发送了2个RST。 由于都是HTTPS的报文,无法获知具体的数据包内容。仔细对比了一下:
- Linux 访问 Nginx ---> Linux先发FIN关闭连接
- Route53 访问 Nginx ---> Nginx先发FIN关闭连接
想一想什么会影响服务端还是客户端主动关闭连接,HTTP Keepalive。 现在基本都是HTTP/1.1,keepalive都是默认启用的,启用http keepalive之后服务端不会主动关闭连接,会是客户端来主动关闭连接。因此判断linux访问Nginx的时候 keepalive是启用的,因此客户端先发FIN;而Route53应当是禁用了keepalive,所以才是Nginx先发FIN。下面继续用curl验证一下:
curl https://10.0.0.125 -H "Connection:close" -vk ----> nginx发送了RST
这样基本可以认定是客户端没有启用keepalive才导致nginx发送了RST。
关于Route53发送的请求是不是真的禁用了keepalive,这一点后续我也是设法保存了TLS的会话密钥,解密了nginx的抓包,证实了Route53发来的请求header里确实是 Connection:close。
Linux 访问 Nginx在Nginx的抓包, 172.31.27.54是linux客户端,10.0.0.125是nginx
02:28:24.667497 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [S], seq 4110578111, win 26883, options [mss 8460,sackOK,TS val 686813194 ecr 0,nop,wscale 7], length 0
02:28:24.667522 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [S.], seq 4170480324, ack 4110578112, win 62643, options [mss 8961,sackOK,TS val 2212977706 ecr 686813194,nop,wscale 7], length 0
02:28:24.668443 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [.], ack 1, win 211, options [nop,nop,TS val 686813195 ecr 2212977706], length 0
02:28:24.669278 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [P.], seq 1:518, ack 1, win 211, options [nop,nop,TS val 686813196 ecr 2212977706], length 517
02:28:24.669286 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [.], ack 518, win 486, options [nop,nop,TS val 2212977708 ecr 686813196], length 0
02:28:24.670207 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [P.], seq 1:1522, ack 518, win 486, options [nop,nop,TS val 2212977709 ecr 686813196], length 1521
02:28:24.671062 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [.], ack 1522, win 234, options [nop,nop,TS val 686813198 ecr 2212977709], length 0
02:28:24.672451 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [P.], seq 518:644, ack 1522, win 234, options [nop,nop,TS val 686813199 ecr 2212977709], length 126
02:28:24.672613 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [P.], seq 1522:1573, ack 644, win 486, options [nop,nop,TS val 2212977711 ecr 686813199], length 51
02:28:24.678023 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [P.], seq 644:764, ack 1573, win 234, options [nop,nop,TS val 686813205 ecr 2212977711], length 120
02:28:24.678258 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [P.], seq 1573:2450, ack 764, win 486, options [nop,nop,TS val 2212977717 ecr 686813205], length 877
02:28:24.678315 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [P.], seq 2450:2481, ack 764, win 486, options [nop,nop,TS val 2212977717 ecr 686813205], length 31
02:28:24.678343 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [F.], seq 2481, ack 764, win 486, options [nop,nop,TS val 2212977717 ecr 686813205], length 0
02:28:24.680395 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [.], ack 2482, win 258, options [nop,nop,TS val 686813207 ecr 2212977717], length 0
02:28:24.680471 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [P.], seq 764:795, ack 2482, win 258, options [nop,nop,TS val 686813207 ecr 2212977717], length 31
02:28:24.680483 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [R], seq 4170482806, win 0, length 0
02:28:24.680598 IP 172.31.27.54.37672 > 10.0.0.125.443: Flags [F.], seq 795, ack 2482, win 258, options [nop,nop,TS val 686813207 ecr 2212977717], length 0
02:28:24.680604 IP 10.0.0.125.443 > 172.31.27.54.37672: Flags [R], seq 4170482806, win 0, length 0
Nginx应当是传输完毕数据之后,发送FIN关闭连接,在此之后收到linux发来的数据报文回复了reset,之后收到linux发送的FIN,又回复了reset。
Nginx分析
这个时候我想测试一下http的请求会不会出现这个情况。结果测试HTTP的请求不论有没有keepalive,都不会出现RST。这个情况只在HTTPS的请求中出现。启用了Nginx的debug模式,但看起来没有任何异常的输出,应用程序这层面应该没什么问题,那么这个时候有必要看一下Nginx的代码,了解下关闭连接的具体逻辑了。
2025/01/31 14:03:24 [debug] 17615#17615: *174 SSL_write: 848
2025/01/31 14:03:24 [debug] 17615#17615: *174 http write filter 0000000000000000
2025/01/31 14:03:24 [debug] 17615#17615: *174 http copy filter: 0 "/index.html?"
2025/01/31 14:03:24 [debug] 17615#17615: *174 http finalize request: 0, "/index.html?" a:1, c:2
2025/01/31 14:03:24 [debug] 17615#17615: *174 http request count:2 blk:0
2025/01/31 14:03:24 [debug] 17615#17615: *174 http finalize request: -4, "/index.html?" a:1, c:1
2025/01/31 14:03:24 [debug] 17615#17615: *174 http request count:1 blk:0
2025/01/31 14:03:24 [debug] 17615#17615: *174 http close request
2025/01/31 14:03:24 [debug] 17615#17615: *174 http log handler
2025/01/31 14:03:24 [debug] 17615#17615: *174 run cleanup: 00000000145F5E48
2025/01/31 14:03:24 [debug] 17615#17615: *174 file cleanup: fd:12
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 00000000145F5050, unused: 0
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 00000000145F9A90, unused: 1710
2025/01/31 14:03:24 [debug] 17615#17615: *174 close http connection: 3 <-----ngx_http_close_connection
2025/01/31 14:03:24 [debug] 17615#17615: *174 SSL_shutdown: 1
2025/01/31 14:03:24 [debug] 17615#17615: *174 reusable connection: 0
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 00000000145E79A0
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 00000000145F8490
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 00000000145FBF00, unused: 24
2025/01/31 14:03:24 [debug] 17615#17615: *174 free: 000000001458A6B0, unused: 400
结合debug的信息,找到ngx_http_close_connection函数负责关闭HTTP层面的连接,首先调用ngx_ssl_shutdown终止SSL会话,之后调用ngx_close_connection关闭TCP层面的连接。
在ngx_close_connection中,调用的是ngx_close_socket函数,该函数的宏定义是close,即双向关闭,这个时候就不能再读写socket了,那么收到数据之后回复reset倒是比较合理,但为什么对面发送FIN还会回复reset呢?
协议栈分析
这些reset很可能跟当时socket所处的状态有关,但一次curl命令马上就执行完了,因此在nginx上用bcc工具看一下。
SKADDR C-PID C-COMM LADDR LPORT RADDR RPORT OLDSTATE -> NEWSTATE MS
ffff8f8dca2eb780 0 swapper/0 0.0.0.0 443 0.0.0.0 0 LISTEN -> SYN_RECV 0.000
ffff8f8dca2eb780 0 swapper/0 10.0.0.125 443 172.31.27.54 37786 SYN_RECV -> ESTABLISHED 0.007
ffff8f8dca2eb780 17615 nginx 10.0.0.125 443 172.31.27.54 37786 ESTABLISHED -> FIN_WAIT1 6.115
ffff8f8dca2eb780 0 swapper/0 10.0.0.125 443 172.31.27.54 37786 FIN_WAIT1 -> FIN_WAIT2 2.264
ffff8f8dca2eb780 0 swapper/0 10.0.0.125 443 172.31.27.54 37786 FIN_WAIT2 -> CLOSE 0.002
由于nginx是主动关闭的一方,因此ESTABLISHED变为FIN_WAIT1再变为FIN_WAIT2是符合预期的,理论上主动关闭的一方会出现timewait状态,bcc却没有显示timewait。结合抓包,nginx发送rst是在FIN_WAIT2的状态,这个令人费解,因此分析一下内核代码。
内核代码分析
总的来看,这个情况需要分析socket状态变化,数据包接收,数据包发送,因此使用ebpf在一些重要的内核函数上打了探针,包括ip_local_out,tcp_set_state,inet_sock_set_state,tcp_v4_do_rcv,tcp_rcv_state_process,tcp_done等等。最终呈现出来的Nginx这边关闭连接过程如下:
- Nginx发送最后的数据给客户端Linux
- Nginx调用close关闭TCP连接,socket状态从ESTABLISHED变为FIN_WAIT1,Nginx发送FIN。
- Linux仅回复ACK,socket状态从FIN_WAIT1变为FIN_WAIT2,之后socket进入TIME_WAIT状态。
- 收到linux发来的PSH报文,回复RST。
- 收到linux发来的FIN报文,回复RST。
内核里负责设置tcp状态的函数是tcp_set_state,在FIN_WAIT1状态下收到ACK之后设置状态为FIN_WAIT2,但之后要判断FIN_WAIT2要持续多长时间,相关函数是tcp_fin_time,这个时间的设置一般是内核参数tcp_fin_timeout。而TCP_TIMEWAIT_LEN是TIMEWAIT状态的等待时间,也就是2MSL,我这里nginx的内核设置为60,和tcp_fin_timeout是相等的。这里收到的数据包只是ACK,不是FIN,因此socket进入timewait状态,相关函数tcp_time_wait。
[root@ip-10-0-0-125 ec2-user]# cat /proc/sys/net/ipv4/tcp_fin_timeout
60
tmo = tcp_fin_time(sk);
if (tmo > TCP_TIMEWAIT_LEN) {
inet_csk_reset_keepalive_timer(sk, tmo - TCP_TIMEWAIT_LEN);
} else if (th->fin || sock_owned_by_user(sk)) {
/* Bad case. We could lose such FIN otherwise.
* It is not a big problem, but it looks confusing
* and not so rare event. We still can lose it now,
* if it spins in bh_lock_sock(), but it is really
* marginal case.
*/
inet_csk_reset_keepalive_timer(sk, tmo);
} else {
tcp_time_wait(sk, TCP_FIN_WAIT2, tmo);
goto discard;
}
tcp_time_wait里面会分配一个新的inet_timewait_sock类型的socket,这样可以节约存储空间,这个结构体中包含两个状态,一个是timewait状态,另一个是子状态是finwait2,这代表是从finwait2进入的timewait。之后安排定时器等过了超时时间就销毁timewait socket。最后一步还调用了tcp_done函数,在这里用tcp_set_state把socket状态设置为了CLOSE。
这么一来,收到ACK就已经进入了timewait状态,再看下后面收到这两个数据包是如何生成的RST。
分析调用栈
第一次reset
tcp_v4_send_reset+1
tcp_v4_rcv+774
tcp_v4_rcv的相关代码如下,查到收到的数据包所属socket已经timewait socket了,进一步使用tcp_timewait_state_process处理,数据包是携带了新数据,因此被reset,之后释放socket。
lookup:
sk = __inet_lookup_skb(&tcp_hashinfo, skb, __tcp_hdrlen(th), th->source,
th->dest, sdif, &refcounted);
if (!sk)
goto no_tcp_socket;
if (sk->sk_state == TCP_TIME_WAIT)
goto do_time_wait;
do_time_wait:
switch (tcp_timewait_state_process(inet_twsk(sk), skb, th))
case TCP_TW_RST:
tcp_v4_send_reset(sk, skb);
inet_twsk_deschedule_put(inet_twsk(sk));
goto discard_it;
第二次reset
tcp_v4_send_reset+1
tcp_v4_do_rcv+476
tcp_v4_rcv+3499
socket已经被销毁了,因此按照listen状态处理,由于携带了ACK标志,被reset。
if (tcp_rcv_state_process(sk, skb)) {
rsk = sk;
goto reset;
}
int tcp_rcv_state_process(struct sock *sk, struct sk_buff *skb)
case TCP_LISTEN:
if (th->ack)
return 1;
reset:
tcp_v4_send_reset(rsk, skb);
现在就算找到了HTTP GET请求的TCP短链接产生了两次RST的原因。分析下来,有如下特点:
- 每一端关闭连接的时候先关闭SSL会话,发送close notify,而rfc5246要求另一端也需要回复close notify。
- 关闭SSL会话之后会再发送FIN关闭TCP会话,收到FIN需要回复ACK。
- Close notify报文会携带PSH标志位。
下面考虑一下能否进行调整不产生RST。
从客户端考虑
客户端启用HTTP Keepalive,就不会在Nginx产生RST了。分析后发现,客户端先发送了close notify,但是Nginx并没有回复close notify,而是直接回复了一个FIN,虽然比较奇怪,但好歹不会在两端产生RST。
Route53是一类托管服务,是外部无法控制的,不知道为什么设计禁用keepalive,但能使用其他监控类的启用http keepalive的服务是一个解决办法。
从服务端考虑
如果nginx要适配禁用keepalive的话,那么就要准备好close之后还要收取一个close notify报文,也就是不能关闭写。即函数从close改为shutdown(rd)即可。