--- 摄于 2017 年 9 月 藏川线前段
--- 摄于 2017 年 9 月 藏川线前段
当前，一般服务都会部署在云服务上，云服务提供商一般会内置一些奇怪的服务，同时云容器大行其道，k8s 的方案带来了可见的动态扩展能力，这已经是一个大趋势了。但这些服务带来的不仅仅是方便，而是整体性地提高了系统的复杂性，尤其是网络环境的复杂性，定位网络问题的流程将变得无比漫长。
经报告，线上生产服务器突然莫名频繁多了一个错误日志：
service error: HandshakeError(Timeout("deadline has elapsed"))
这个错误在以往基本没见过，最近突然多了起来，很不正常，经过查询，在低版本的服务中确实没有看到过这个日志，那么问题出在哪？
在没有思路的情况下，首先确认该日志报告的问题是什么，这是 tentacle 库的 secio 协议的握手超时报错，默认是 10s，正常来说，就算是跨洲握手也不至于超过 10s 无响应，这个服务是部署在 k8s 内的，提出定位问题的思路：
因为该生产服务器本人无法访问，这一波提出问题之后，我就不再关注该问题了，直到几天之后，问题有了新的进展。
打开 debug 日志之后发现，握手超时的 ip 就是想要连接的 ip，用 nc 测试网络是通的，secio 是套娃在 TCP 上的一层加密协议，握手就是经典的 ECDH 过程，握手过程的消息传输就 200-400 bytes，理论上超时的可能性非常小。
随后打开 trace 日志，查看握手过程的追踪日志，发现，无论是客户端还是服务器，ECDH 过程在发出第一步 proposal 的之后，就再也没有继续执行了，直到超时，从这里看，报错是合理的，但为什么会有这样的状态呢？
经过一番搜索之后，发现了云服务商会搞事的文章，文章的意思是说，为了做服务活性监控，提供了一种功能，对服务的 TCP 监听端口进行连接测试，然后直接发 RST 断开连接，这是一个不好的文明。。。
接着测试是否是因为这种问题导致握手出现问题，用 nc 模拟被扫端口的场景，发现似乎复现了，而且 gnu 的 nc 与 bsd 的 nc 行为还不太一致，这里令我想到一个问题，无论是什么协议，它必然有解析规则，无论是加密还是非加密，只要错了一个地方，协议就会解析错误，进而导致意外断开，这是无法避免的事情。secio 的握手使用的是 length codec，如果有恶意用户注入一个 u64 max 进去，那握手失败是必然的事情，无人能避免这种问题。
本以为此事到此基本结束，降低该云服务商的探测间隔就好了，没想到，还有后续。。。
半个月之后，再次报告，还是会频繁出现相同的问题。这次直接上 tcpdump 抓包了，必须看一下服务器上到底发出去东西没有，不然这个问题始终无法解决，因为数据有点多，这里就贴关键部分（一次连接到断开过程）好了：
1 TCP 80 36766 → 50020 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2685571870 TSecr=0 WS=512
2 TCP 80 50020 → 36766 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2685571857 TSecr=2685571870 WS=512
3 TCP 72 36766 → 50020 [ACK] Seq=1 Ack=1 Win=29696 Len=0 TSval=2685571872 TSecr=2685571857
4 TCP 249 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685571873 TSecr=2685571857
5 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685572077 TSecr=2685571857
6 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685572283 TSecr=2685571857
7 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685572696 TSecr=2685571857
8 TCP 80 [TCP Retransmission] 50020 → 36766 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2685572860 TSecr=2685572696 WS=512
9 TCP 72 [TCP Dup ACK 3#1] 36766 → 50020 [ACK] Seq=178 Ack=1 Win=29696 Len=0 TSval=2685572874 TSecr=2685571857
10 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685573522 TSecr=2685571857
11 TCP 80 [TCP Retransmission] 50020 → 36766 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2685575060 TSecr=2685573522 WS=512
12 TCP 72 [TCP Dup ACK 3#2] 36766 → 50020 [ACK] Seq=178 Ack=1 Win=29696 Len=0 TSval=2685575074 TSecr=2685571857
13 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685575176 TSecr=2685571857
14 TCP 249 [TCP Retransmission] 36766 → 50020 [PSH, ACK] Seq=1 Ack=1 Win=29696 Len=177 TSval=2685578480 TSecr=2685571857
15 TCP 72 36766 → 50020 [FIN, ACK] Seq=178 Ack=1 Win=29696 Len=0 TSval=2685581873 TSecr=2685571857
16 TCP 60 50020 → 36766 [RST] Seq=1 Win=0 Len=0
数据只删除了 ip 信息，其他都在，这是 server 端的抓包信息，各位看官，是否能看出问题在哪呢？可以在这里尝试思考一下可能是什么问题。
TCP 握手流程和状态转换图网上大把，这里就不贴出来了，关键问题在哪呢，仔细看抓包数据第八行，这是一个 retry 过程，而且还是 SYNC ACK，同时 Seq 还等于 0，第一反应是，这里是不是有问题？从 4-7 行可以看到，客户端已经发了 249 bytes 大小的握手数据过来，并且是重试了多次发送，为什么 server 还在尝试响应 SYNC：
server 端并没有成功响应 SYNC ACK，那么客户端为什么认为 TCP 连接建立成功，这不符合逻辑。
server 认为自己没有成功发送 SYNC ACK，进而导致它一直在尝试重发，而 client 端已经接到了 SYNC ACK 并建立了连接，它开始了握手过程。那么 TCP 协议是怎么确认 server 知道 client 接到了 SYNC ACK 的呢，答案是 client 会再对该 ACK 响应一个 ACK，就是第3/9/12行的 ACK，也就是说，client 响应了 ACK 到达了服务器，但被丢掉了，没有完成 TCP Stream 的构建！
从上述分析思路可以看出，这个问题根本不是 secio 上的问题，而是底层 TCP 上出了问题，在 server 端，如果 sync ack 的 ack 没有接到的话，这个 TCP 的握手并没有完成，也就是说，它是一个半开状态，轮不到用户操作，用 epoll 的术语来说，它还没有 writeable，它需要呆在 OS 的半开 queue 中等待响应。
那么是什么问题导致 OS 接到了 ack 却丢掉了呢？这个问题就很奇怪，推测一：OS bug，推测二：有 TCP 相关参数设置问题。
一顿爆搜，找到一篇文章，看上去很相似，在服务器上使用 nstat -s | rg overflowed 查看，发现确实存在泄漏：
$ nstat -s | rg overflowed
10138 times the listen queue of a socket overflowed
TCP Listen 有一个 backlog 参数，用于设置接收从半开状态到完成握手过程的 stream 的 queue 的大小，一般设置为 1024，只要机器不是小霸王，程序写得不那么奇怪，理论上是不可能泄漏的，但这里。。。很奇怪。
从这里开始就需要去定位代码库到底出了什么问题，是哪个 commit 导致的问题，很巧，在测试环境里发现了几个版本的 release 都在同时跑，分别查一下，发现了华点，低版本是没问题的，高版本出现了类似的日志和 overflowed 的状态，对比前后的代码，发现 tentacle 库对 tcp listen 并没有修改，反而是 tokio 版本从 0.24 升级到了 0.25，主要升级的是 mio，而 mio 的这个版本更新，底层 net2 等库变化比较大。于是，直接使用 tokio 1.x 版本测试相同环境，发现无法复现问题，大胆猜测是这里的问题。
值得高兴的是，在定位这个问题的一个月中，tentacle 已经发布了基于 tokio 1.x 的 alpha 版本，并且 ckb develop 分支在我的强烈推动下，已经将该版本合并进去了。
整个定位过程长达一个月，同时上述工作并不是我一个人完成的，毕竟我无法接触到服务器，所以各种测试验证都是团队中其他成员完成的，我提供的帮助仅仅是将问题从 tentacle 库缩减到 secio 再缩减到 TCP 端而已，看到 TCP 握手出现问题，对我来说也是非常惊讶的。
同时，与上篇末尾一样，定位问题的诀窍就是，稳定复现，缩小范围，大胆猜测，小心验证，仅此而已。
请登录后评论
评论区
加载更多