一次网络超时的排查

最近在测试一个分布式组件的时候，发现节点之间会频繁的出现网络传输超时的情况。组件的工作原理如下

节点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，产生丢包的现象也就可以理解了。虽然问题产生的原因很囧，但是这次耗时两天的问题排查还是让我很有收获的，切换了负载之后问题也就成功解决了。