一次网络超时的排查
共 8442字，需浏览 17分钟
·
2021-10-22 08:55
最近在测试一个分布式组件的时候，发现节点之间会频繁的出现网络传输超时的情况。组件的工作原理如下
节点 1 向节点 2 发送心跳包，发送之后等待节点 2 的回应 节点 2 在收到心跳包之后做一些处理，随后发送回复报文给节点 1 节点 1 收到节点 2 回复的报文并退出等待，一次数据传输结束 节点 1 如果一段时间内没有收到节点 2 的回应就会发生超时异常
我们遇到的问题就是节点 1 总是在运行一段时间之后（很短，大约几秒钟），发送给节点 2 的数据就无法及时的得到回应，随后节点 1 报出超时异常。问题在于我们用于测试的机器应该都在同一个机房，而我们设置的超时时间为 50ms，同一个机房的节点延迟怎么会超过 50ms 呢？
日志
因为是分布式系统，并且涉及到网络传输，我们基本上没有办法使用 DEBUG 来进行调试，所以日志成为了排解问题的唯一线索。顺便说一句，在写代码的时候日志应该越详细越好，日志除了打印变量数据，还应该附带好详细的上下文信息。
我们在发送数据和接收数据的地方都打上日志，此外应该对所使用的节点的时间进行校对，我们在分析问题时很依赖于日志中记录的时间信息。
我们执行程序获取日志如下
发送端
2019/08/14 15:18:45.703679 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.753927 node.go:259: 202(me) to 92 AppendEntries timeout and retry
2019/08/14 15:18:45.763991 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.814221 node.go:259: 202(me) to 92 AppendEntries timeout and retry
2019/08/14 15:18:45.824193 node.go:233: 202(me) send AppendEntries to 92
2019/08/14 15:18:45.874455 node.go:259: 202(me) to 92 AppendEntries timeout and retry
我们观察以上日志发现确实发送端在发送了心跳 50ms 后因为没有收到响应随即超时了，接下来我们再观察接收端的日志。根据上面的日志我们已经知道了异常发生在 703ms ~ 874ms 之间，所以我们在观察接收端的日志时应该重点关注 703、763、824 这三个发送了心跳的时间点，接收端有如下日志信息：
2019/08/14 15:18:45.655403 connection.go:387: AppendEntries
2019/08/14 15:18:45.655477 connection.go:95: Read Start
2019/08/14 15:18:45.895077 connection.go:99: Read End
2019/08/14 15:18:45.895112 connection.go:100: Read 1 bytes and cost 239ms 239574218ns
2019/08/14 15:18:45.895379 connection.go:387: AppendEntries
2019/08/14 15:18:45.895439 connection.go:95: Read Start
2019/08/14 15:18:45.895452 connection.go:99: Read End
2019/08/14 15:18:45.895464 connection.go:100: Read 1 bytes and cost 0ms 4203ns
2019/08/14 15:18:45.895711 connection.go:387: AppendEntries
2019/08/14 15:18:45.895766 connection.go:95: Read Start
2019/08/14 15:18:45.895779 connection.go:99: Read End
2019/08/14 15:18:45.895791 connection.go:100: Read 1 bytes and cost 0ms 3862ns
2019/08/14 15:18:45.896082 connection.go:387: AppendEntries
观察接收端的日志我们发现在 655ms 的时候接收端接收到最后一次正常的心跳，随后就被阻塞在 read 调用上，下一次读取到心跳信息则是在 895ms，并且随后很快的就读完了三次心跳的数据。很显然，895 远大于 703、763、824，那么是什么原因导致了发送端在这三个时间点发送的报文一直到 200 多毫秒之后才被接收端成功的读取到呢？
tcpdump
我们使用 tcpdump 工具来获取网络报文信息，从而了解数据的传输情况。因为我们的组件使用 6300 端口进行数据传输，所以在两个节点上面都要执行如下命令来抓取通过 6300 端口的报文
$ tcpdump tcp port 6300
我在上一步执行程序的时候已经打开了 tcpdump 命令，所以现在我们已经可以观察 tcpdump 的输出信息了。首先观察发送端发送的信息，同样我们只关注 703ms ~ 874ms 之间的信息。该时间段的信息如下，需要注意有一些网络数据报文与我们要关注的内容无关，直接忽略即可。
15:18:45.643425 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 525:546, ack 164, win 114, options [nop,nop,TS val 3450638986 ecr 3259647687], length 21
15:18:45.664930 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [P.], seq 164:170, ack 546, win 115, options [nop,nop,TS val 3259647744 ecr 3450638986], length 6
15:18:45.703607 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 546:567, ack 170, win 114, options [nop,nop,TS val 3450639047 ecr 3259647744], length 21
15:18:45.763909 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 567:588, ack 170, win 114, options [nop,nop,TS val 3450639107 ecr 3259647744], length 21
15:18:45.784473 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647863 ecr 3450638986,nop,nop,sack 1 {567:588}], length 0
15:18:45.824084 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 588:609, ack 170, win 114, options [nop,nop,TS val 3450639167 ecr 3259647863], length 21
15:18:45.840677 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647920 ecr 3450638986,nop,nop,sack 1 {567:609}], length 0
15:18:45.869809 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [P.], seq 170:183, ack 546, win 115, options [nop,nop,TS val 3259647948 ecr 3450638986,nop,nop,sack 1 {567:609}], length 13
15:18:45.870435 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 609:615, ack 183, win 114, options [nop,nop,TS val 3450639213 ecr 3259647948], length 6
15:18:45.884354 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 615:636, ack 183, win 114, options [nop,nop,TS val 3450639227 ecr 3259647948], length 21
15:18:45.886702 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647966 ecr 3450638986,nop,nop,sack 1 {567:615}], length 0
15:18:45.886732 IP lin-21-34-202.bmc-grx > 172.21.3.92.57619: Flags [P.], seq 546:567, ack 183, win 114, options [nop,nop,TS val 3450639230 ecr 3259647948], length 21
15:18:45.902699 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647981 ecr 3450638986,nop,nop,sack 1 {567:636}], length 0
15:18:45.903892 IP 172.21.3.92.57619 > lin-21-34-202.bmc-grx: Flags [.], ack 636, win 115, options [nop,nop,TS val 3259647983 ecr 3450639230], length 0
其中 lin-21-34-202 是节点 1，172.21.3.92.57619 是节点 2，即心跳是由 lin-21-34-202 发送给 172.21.3.92 的。Flags 中的 P 代表 PUSH， . 代表 ACK。
已知我们心跳的长度为 12，由上面的报文以及前面的日志我们可以推测出来，第一行的信息代表了最后一次节点 1 给节点 2 发送的正常心跳信息。
随后节点 1 发送了 seq 为 546:567 和 567:588 的两条心跳包，这就是第 3 第 4 行的信息。奇怪的是在第 5 行所代表的节点 2 回复的 ACK 中，只表示收到了 567:588 的的数据包，没有 546:567。第 6 第 7 行表示了发送的第三个心跳包 588:609 以及相应的 ACK 567:609。
节点 1 发现节点 2 迟迟不回复 546:567 的 ACK，就对 546:567 进行了重发，这就是第 12 行的信息。这一次节点 2 终于回复了 ACK（第 14 行），我们可以认为 546:567 确定被发送到节点 2 了。
随后我们再看一下接收端的报文信息
15:18:45.654608 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 525:546, ack 164, win 114, options [nop,nop,TS val 3450638986 ecr 3259647687], length 21
15:18:45.655249 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [P.], seq 164:170, ack 546, win 115, options [nop,nop,TS val 3259647744 ecr 3450638986], length 6
15:18:45.774317 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 567:588, ack 170, win 114, options [nop,nop,TS val 3450639107 ecr 3259647744], length 21
15:18:45.774348 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647863 ecr 3450638986,nop,nop,sack 1 {567:588}], length 0
15:18:45.831770 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 588:609, ack 170, win 114, options [nop,nop,TS val 3450639167 ecr 3259647863], length 21
15:18:45.831795 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647920 ecr 3450638986,nop,nop,sack 1 {567:609}], length 0
15:18:45.859801 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [P.], seq 170:183, ack 546, win 115, options [nop,nop,TS val 3259647948 ecr 3450638986,nop,nop,sack 1 {567:609}], length 13
15:18:45.877852 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 609:615, ack 183, win 114, options [nop,nop,TS val 3450639213 ecr 3259647948], length 6
15:18:45.877870 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647966 ecr 3450638986,nop,nop,sack 1 {567:615}], length 0
15:18:45.892884 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 615:636, ack 183, win 114, options [nop,nop,TS val 3450639227 ecr 3259647948], length 21
15:18:45.892901 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 546, win 115, options [nop,nop,TS val 3259647981 ecr 3450638986,nop,nop,sack 1 {567:636}], length 0
15:18:45.894971 IP 172.21.34.202.bmc-grx > lin-21-3-92.57619: Flags [P.], seq 546:567, ack 183, win 114, options [nop,nop,TS val 3450639230 ecr 3259647948], length 21
15:18:45.894989 IP lin-21-3-92.57619 > 172.21.34.202.bmc-grx: Flags [.], ack 636, win 115, options [nop,nop,TS val 3259647983 ecr 3450639230], length 0
接收端的报文基本上就是发送端的镜像，但是有趣的是接收端的报文只有 13 条，而发送端则发送了 14 条报文。仔细对比就发现发送端的 seq 546:567 在接收端不存在，看来这个报文在网络传输中丢失了没能成功到达节点 2。节点 2 在节点 1 再次重传后才最终获取了 546:567 的报文信息，即接收端的第 12 行，此时时间点为 15:18:45.894971，最后节点 2 返回给节点 1 ACK。
分析
观察上面接收端收到重传数据的时间为 15:18:45.894971，日志中接收端用户态成功读取到报文的时间为 15:18:45.895077，那结果就明显了。
节点 1 发送给节点 2 的第一个心跳包丢失了，因为 TCP 协议中数据的有序性，所以虽然后面的数据成功到达也不能将这些数据返回给用户态程序。一直到节点 1 因为没能得到 ACK 而进行超时重传，节点 2 最终获取了心跳包 1，此时数据已经完整可以返回给用户态程序。这一顿操作也导致这部分数据从节点 1 的用户态到节点 2 的用户态之间产生了 894 - 703 约 200ms 的延迟，因而节点 1 产生了超时。
解决
咦，为什么同一个机房的两个机器之间会丢包呢，难道路由器出问题了？经过检查之后发现是我们自己搞错了，在申请机器的时候我们第一次申请的机器在南京，第二次申请的机器在杭州，所以这两个机器其实并不是在一个机房并且之间隔了接近 300km，产生丢包的现象也就可以理解了。虽然问题产生的原因很囧，但是这次耗时两天的问题排查还是让我很有收获的，切换了负载之后问题也就成功解决了。
原文链接：https://www.nosuchfield.com/2019/08/14/Network-timeout-troubleshooting/
你可能还喜欢
点击下方图片即可阅读
云原生是一种信仰 🤘
关注公众号
后台回复◉k8s◉获取史上最方便快捷的 Kubernetes 高可用部署工具，只需一条命令，连 ssh 都不需要！
点击 "阅读原文" 获取更好的阅读体验！
发现朋友圈变“安静”了吗？
