记一次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这边关闭连接过程如下:

  1. Nginx发送最后的数据给客户端Linux
  2. Nginx调用close关闭TCP连接,socket状态从ESTABLISHED变为FIN_WAIT1,Nginx发送FIN。
  3. Linux仅回复ACK,socket状态从FIN_WAIT1变为FIN_WAIT2,之后socket进入TIME_WAIT状态。
  4. 收到linux发来的PSH报文,回复RST。
  5. 收到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的原因。分析下来,有如下特点:

  1. 每一端关闭连接的时候先关闭SSL会话,发送close notify,而rfc5246要求另一端也需要回复close notify。
  2. 关闭SSL会话之后会再发送FIN关闭TCP会话,收到FIN需要回复ACK。
  3. 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)即可。


发表评论

  • OωO
  • |´・ω・)ノ
  • ヾ(≧∇≦*)ゝ
  • (☆ω☆)
  • (╯‵□′)╯︵┴─┴
  •  ̄﹃ ̄
  • (/ω\)
  • ∠(ᐛ」∠)_
  • (๑•̀ㅁ•́ฅ)
  • →_→
  • ୧(๑•̀⌄•́๑)૭
  • ٩(ˊᗜˋ*)و
  • (ノ°ο°)ノ
  • (´இ皿இ`)
  • ⌇●﹏●⌇
  • (ฅ´ω`ฅ)
  • (╯°A°)╯︵○○○
  • φ( ̄∇ ̄o)
  • (งᵒ̌皿ᵒ̌)ง⁼³₌₃
  • (ó﹏ò。)
  • Σ(っ°Д°;)っ
  • ╮(╯▽╰)╭
  • o(*
  • >﹏<
  • (。•ˇ‸ˇ•。)
  • 泡泡
  • 颜文字

*