Cloud 产品中有关 TCP RST 的问题排查过程

更新时间 8/8/2022

最近在项目中遇到了一个因为 TCP RST 而导致集成测试用例运行失败的问题,简单用文字在此跟大家分享一下。

背景信息

我们的后端项目是包含了多个组件的微服务系统,数据库使用的是 Postgres。通常在进行集成测试时,我们会使用 Kind 将整个后端组件以及依赖的 Postgres、Redis 等中间件运行起来,然后通过 port-forward 方式暴露到宿主机上,这样运行在宿主机上的 Ginkgo (Golang 集成测试框架)就可以访问到 Kind 中运行的后端服务了。这一套测试框架在依赖 Kubernetes 的项目中比较常见,使用起来也很便捷。

而这次的问题出现在,我们将集成测试中的 k8s.io/client-go 依赖从 v0.22.4 升级到 v0.24.0 版本后,测试用例中通过 port-forward 方式访问 Postgres 时,总是会出现失败的情况。

排查过程一:分析并找到初步原因

锁定 Port-Forward 断开的原因

刚发现问题的时候,我们并不知道是因为升级 k8s.io/client-go 导致的问题,因为出现问题的 Pull Request 中还有很多其他的变更。所以我们首先还是通过查看错误日志,得到了如下信息:

1E0610 07:20:46.199054   25339 portforward.go:406] an error occurred forwarding 35169 -> 5432: error forwarding port 5432 to pod d9229db6040a461f038cf546c5efc39c407f48d015b603855882f2a94a9c028a, uid : failed to execute portforward in network namespace "/var/run/netns/cni-d75c685d-0da5-a6c9-9891-ffba16e23531": read tcp4 127.0.0.1:51062->127.0.0.1:5432: read: connection reset by peer
2E0610 07:20:46.199530   25339 portforward.go:234] lost connection to pod

对比了旧代码的运行日志,发现其中也会打印第一行日志,但是没有第二行 lost connection to pod。 根据这个关键信息,我们继续翻看了 kubernetes portforward 包下的代码:

1// wait for interrupt or conn closure
2select {
3case <-pf.stopChan:
4case <-pf.streamConn.CloseChan():
5        runtime.HandleError(errors.New("lost connection to pod"))
6}

上述代码显示,只有在 pf.streamConn 被关闭时才会打印 lost connection to pod,搜索 pf.streamConn.Close() 相关代码,最终锁定了以下信息:

1// always expect something on errorChan (it may be nil)
2err = <-errorChan
3if err != nil {
4        runtime.HandleError(err)
5        pf.streamConn.Close()
6}

Git Blame 这段代码,发现是由于该 PR 实现的一个优化导致了问题。

该 PR 涉及的优化细节为:在 port-forward 的 Pod 侧连接(kubelet -> postgres)出现 error 时,让 port-forward 自身被关闭。这是为了解决 kubectl 对某个 pod 执行了 port-forward 后,该 pod 死掉的情况下(比如被删除了),kubectl 可以自动退出,而不至于一直继续运行。

经过上面的分析,我们锁定了是因为 port-forward 在 pod 侧的连接出现了 error,结合日志 read tcp4 127.0.0.1:51062->127.0.0.1:5432: read: connection reset by peer 分析,也就是说在 kubelet 发起的 51062 端口到 Postgres 5432 的 TCP 连接中,出现了 Postgres 发出的 TCP RST 包。

为什么 Postgres 会发出 TCP RST 包?

下一步就是要分析为什么 Postgres 会发出 RST 包。在这里,我们可以使用最新版本(v1.24.2)的 kubectl 来尝试复现集成测试中遇到的问题。

首先开启 port-forward。

1./kubectl port-forward pod/postgres-0 5432:5432
2Forwarding from 127.0.0.1:5432 -> 5432
3Forwarding from [::1]:5432 -> 5432

然后使用 psql 通过 port-forward 查询 Postgres。需注意,由于我们的 Postgres 开启了客户端证书校验,所以需要为 psql 指定客户端证书和私钥。

1PGPASSWORD="123456" PGSSLCERT=./tls.crt PGSSLKEY=./tls.key psql -t -h 127.0.0.1 -U postgres -d postgres -c "select 1;"

port-forward 日志打印如下:

1Handling connection for 5432
2E0711 00:01:28.334216 3041058 portforward.go:406] an error occurred forwarding 5432 -> 5432: error forwarding port 5432 to pod ebb9210ccf74b8047be4c6e8a23237c460a33235b2f6c65430ecd680f70e71cf, uid : failed to execute portforward in network namespace "/var/run/netns/cni-d8bfc8cf-2434-540c-9e60-f71f81de7ac0": read tcp4 127.0.0.1:36252->127.0.0.1:5432: read: connection reset by peer
3E0711 00:01:28.334458 3041058 portforward.go:234] lost connection to pod

在复现的同时,我们使用 tcpdump 抓取 postgres 5432 端口的包以及使用 strace 记录 Postgres 进程发起的系统调用。根据复现异常时的日志中 36252 端口作为关键字,在 tcpdump 和 strace 输出中过滤得到如下信息。

tcpdump 输出信息:

100:01:28.330748 IP 127.0.0.1.36252 > 127.0.0.1.5432: Flags [P.], seq 1866:1903, ack 2595, win 512, options [nop,nop,TS val 2518407611 ecr 2518407610], length 37
200:01:28.330750 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [.], ack 1903, win 512, options [nop,nop,TS val 2518407611 ecr 2518407611], length 0
300:01:28.331087 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [P.], seq 2595:2683, ack 1903, win 512, options [nop,nop,TS val 2518407611 ecr 2518407611], length 88
400:01:28.331789 IP 127.0.0.1.36252 > 127.0.0.1.5432: Flags [P.], seq 1903:1930, ack 2683, win 512, options [nop,nop,TS val 2518407612 ecr 2518407611], length 27
500:01:28.331793 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [.], ack 1930, win 512, options [nop,nop,TS val 2518407612 ecr 2518407612], length 0
600:01:28.331803 IP 127.0.0.1.36252 > 127.0.0.1.5432: Flags [P.], seq 1930:1954, ack 2683, win 512, options [nop,nop,TS val 2518407612 ecr 2518407612], length 24
700:01:28.331805 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [.], ack 1954, win 512, options [nop,nop,TS val 2518407612 ecr 2518407612], length 0
800:01:28.332296 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [P.], seq 2683:2707, ack 1954, win 512, options [nop,nop,TS val 2518407613 ecr 2518407612], length 24
900:01:28.333718 IP 127.0.0.1.5432 > 127.0.0.1.36252: Flags [R.], seq 2707, ack 1954, win 512, options [nop,nop,TS val 2518407614 ecr 2518407612], length 0

strace 输出信息:

13431299 accept(3, {sa_family=AF_INET, sin_port=htons(36252), sin_addr=inet_addr("127.0.0.1")}, [128->16]) = 9
23431299 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fbba752ec50) = 1323730
33431299 close(9)
4...
51323730 fcntl(9, F_GETFL)               = 0x2 (flags O_RDWR)
61323730 fcntl(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
7...
81323730 recvfrom(9, "\27\3\3\0 ", 5, 0, NULL, NULL) = 5
91323730 recvfrom(9, "...", 32, 0, NULL, NULL) = 32
101323730 sendto(9, "...", 88, 0, NULL, 0) = 88
111323730 recvfrom(9, "\27\3\3\0\26", 5, 0, NULL, NULL) = 5
121323730 recvfrom(9, "...", 22, 0, NULL, NULL) = 22
131323730 sendto(9, "...", 24, 0, NULL, 0) = 24
141323730 exit_group(1)                   = ?
151323730 +++ exited with 1 +++

通过分析上述 strace 结果,我们会发现 Postgres 采用了很传统的进程模型,即每个连接启动一个子进程去处理。在上述日志中,3431299 进程在接收到新的连接(36252 -> 5432)时克隆出了 1323730 子进程去处理。

通过对比 tcpdump 和 strace 的输出,会发现来自 36252 最后一个 24 字节大小的包没有被 1323730 进程读取,而这正是导致内核返回 RST 包的原因。

在正常情况下,如果进程退出或者对 Socket 主动执行 Close 系统调用,内核会发出 FIN 包,进入四次挥手流程。但是在当前的场景下,内核发现在断开连接时还存在一些数据没有被应用层读取,应用就已经退出的情况,导致内核不得不使用 RST 包,以此来告诉客户端“你发送的一些数据没有被服务端读取,这是一次异常的 TCP 断连”。

那么这个没有被读取的 24 字节包到底是什么呢?

24 字节包

前文中提到我们使用的 Postgres 是开启了 mTLS 模式的,所以整个连接都是 TLS。在断开连接时,就会发出 TLS 协议中的 “Close Notify” 包。下图展示了一个 TLS 连接的生命周期:

TLS 连接生命周期图

结合到 Postgres TLS 连接场景下,Client (psql)和 Server(Postgres)都会给对方发送 close_notify,但是也都没有等对方的响应就直接关闭了 TCP 连接,所以两边都各自产生了一个 RST,下面是 psql 侧抓包的结果:

100:36:56.015219 IP 127.0.0.1.39248 > 127.0.0.1.5432: Flags [P.], seq 1903:1930, ack 2683, win 512, options [nop,nop,TS val 2520535295 ecr 2520535295], length 27
200:36:56.015229 IP 127.0.0.1.39248 > 127.0.0.1.5432: Flags [P.], seq 1930:1954, ack 2683, win 512, options [nop,nop,TS val 2520535295 ecr 2520535295], length 24
300:36:56.015426 IP 127.0.0.1.39248 > 127.0.0.1.5432: Flags [F.], seq 1954, ack 2683, win 512, options [nop,nop,TS val 2520535296 ecr 2520535295], length 0
400:36:56.015427 IP 127.0.0.1.5432 > 127.0.0.1.39248: Flags [.], ack 1954, win 512, options [nop,nop,TS val 2520535296 ecr 2520535295], length 0
500:36:56.016076 IP 127.0.0.1.5432 > 127.0.0.1.39248: Flags [P.], seq 2683:2707, ack 1955, win 512, options [nop,nop,TS val 2520535296 ecr 2520535296], length 24
600:36:56.016104 IP 127.0.0.1.39248 > 127.0.0.1.5432: Flags [R], seq 2542047690, win 0, length 0

前三个包分别是 Postgres 协议中的 Termination、SSL 层的 close_notify 和 TCP 层 FIN。psql 一次性就把自己断开连接要发送的指令都发完了,结果服务端又返回了一个 SSL close_notify。

此时因为这个 Socket 的 fd 已经被 psql 关掉了,内核也就知道这个数据包 psql 是没法读取的了,也就不得不出现一个 RST 了。

总结

经过上面的分析可以看出,在 Postgres 开启 TLS 模式的前提下,客户端跟 Postgres 的连接断开流程中一定会产生 RST,所以我们暂时调高了集成测试中 Postgres 客户端的 IdleTimeout,让连接在测试运行过程中不要断开,一直保持连接状态,暂时绕过了这个问题。

排查过程二:解决新问题

Postgres 的问题暂时解决后,很快又发现了新的问题。一些关于 APISIX HTTPS 的测试用例会出现偶发挂掉。

通过查看日志,我们发现对于 APISIX HTTPS 端口的 port-forward 挂掉状况,总是发生在请求了 60s 后,跟默认的 keepalive_timeout 配置符合。通过抓包,我们确定了闲置的连接确实在 60s 后被 APISIX 主动断开了。以下是断开连接时的抓包截图:

抓包截图 1

通过图中信息可以看到,这次断开连接的流程确实存在 RST 包,原因与 Postgres 场景下类似。即 APISIX 断开连接时会发出 ssl close notify 包,客户端收到后会回复 ssl close notify,但是 APISIX 并没有读取客户端发送的这条返回信息。

但问题是发生在上述断开连接的流程中, port-forward 并没有因为这个 RST 包被关闭掉。原因是 APISIX 已经发出了 FIN 包,kubelet 在收到 FIN 包后(read EOF),也开始关闭自己的 fd,也就不会再读取这个 fd 了,所以这个 RST 对它没有影响。

但同时我们注意到,APISIX 发送 SSL Close Notify(SSL_shutdown) 和发出 FIN (close)其实是两次顺序执行的调用,那么有没有可能是在这两步之间,客户端的 SSL Close Notify 横插一脚,也就是说 FIN 包还没有发出去,客户端的 SSL Close Notify 就已经到了(因为整个网络都是在同一台宿主机上,延迟很低),此时就可能会导致 RST。

思来想去我们认为只有上面这种可能,便开始尝试复现这种情况。首先将 APISIX 的 keepalive timeout 配置调小(3s),这样可以快速模拟 timeout 后断开连接,然后执行一个客户端每次发起 10 个连接,等待 APISIX 关闭连接。循环执行,直到 port-forward 挂掉,在一段时间后,果然复现了问题,以下是异常请况下的抓包截图:

抓包截图 2

抓包结果显示,上述猜想是正确的。

总结

在网络延迟很低的情况下,由 APISIX 主动断开的 SSL 连接可能会触发 RST,所以我们在集成测试中将客户端的 keepalive timeout 配置为小于 APISIX 的 60s,这样就可以让客户端先断开连接,也就不会触发 APISIX 可能发出 RST 的情况。

后记

可以看到 APISIX 和 Postgres 在断开 SSL 连接时,都不会理会客户端的 Close Notify,TLS 的标准中可能压根也没有规定一定要读取对端的 Close Notify 包,而这正是导致出现 TCP RST 的根本原因。

以上就是本次分析 RST 问题的全部过程,其中关于 Postgres、Kubelet 、APISIX、内核等行为的分析大多都是基于使用 tcpdump 和 strace 观测所得,尚没有深入到源码,所以在理解上可能有误,欢迎大家指摘。但整个分析思路和方法对类似的 RST 问题是通用的,可以进行相关参考。