Written by arstercz - 2017-08-03

tcpdump 在 bond 环境下抓到重复报文的问题说明

近期在排查问题时, 使用 tcpdump 抓包发现一个很奇怪的现象, 所有抓到的包都有重复的一份, 使用 wireshark 查看则表现为 tcp out of order, tcp dup ack 以及 tcp retransmission 这三种提示特别多, 如下图所示:

我们在 centos 6 和 centos 7 系统中验证都有这样的问题, 类似情况见 redhat-1260733

下面开始详细介绍该问题的描述及处理细节:

环境说明

10.0.21.5  -  web 主机 - centos6
10.0.21.7  -  redis 主机 - centos7

网络结构

bond 网络结构大致如下: 两台机器的 eth2, eth3 网口分别连接两个交换机, 选择模式 1 进行设置组成了 bond1 网卡. web 主机 eth2 为当前活跃的网卡, redis 主机 eth3 位当前活跃的网卡.

问题说明

在 bond 模式为 1(active-backup 模式) 的网络环境下, 使用 tcpdump 及选项 -i any 抓取 web 主机上所有网卡的报文, 使用 wireshark 发现所有的接收和发送都有重复的报文, 而对端的 redis 主机则一切正常.出现的现象如上图所示, 使用以下命令进行抓包测试:

1. web 主机上抓包:
tcpdump -S -s 0 -n -n -i any port 6380 -w 6380.pcap

2.在 web 主机的另一个会话中, 执行 telnet
telnet 10.0.21.7 6380
Trying 10.0.21.7...
Connected to 10.0.21.7.
Escape character is '^]'.
^]
telnet> quit
Connection closed.

web 主机上抓到的包类似下面的内容:

18:02.056270 IP 10.0.21.5.24399 > 10.0.21.7.6380: Flags [S], seq 3834591311, win 14600, options [mss 1460,sackOK,TS val 4281235630 ecr 0,nop,wscale 8], length 0
18:02.056275 IP 10.0.21.5.24399 > 10.0.21.7.6380: Flags [S], seq 3834591311, win 14600, options [mss 1460,sackOK,TS val 4281235630 ecr 0,nop,wscale 8], length 0
18:02.056405 IP 10.0.21.7.3302 > 10.0.21.5.24399: Flags [S.], seq 522913168, ack 3834591312, win 14480, options [mss 1460,sackOK,TS val 3589524071 ecr 4281235630,nop,wscale 8], length 0
18:02.056405 IP 10.0.21.7.3302 > 10.0.21.5.24399: Flags [S.], seq 522913168, ack 3834591312, win 14480, options [mss 1460,sackOK,TS val 3589524071 ecr 4281235630,nop,wscale 8], length 0
18:02.056425 IP 10.0.21.5.24399 > 10.0.21.7.6380: Flags [.], ack 1, win 58, options [nop,nop,TS val 4281235631 ecr 3589524071], length 0
18:02.056426 IP 10.0.21.5.24399 > 10.0.21.7.6380: Flags [.], ack 1, win 58, options [nop,nop,TS val 4281235631 ecr 3589524071], length 0
18:02.056560 IP 10.0.21.7.3302 > 10.0.21.5.24399: Flags [P.], seq 1:91, ack 1, win 57, options [nop,nop,TS val 3589524071 ecr 4281235631], length 90
18:02.056560 IP 10.0.21.7.3302 > 10.0.21.5.24399: Flags [P.], seq 1:91, ack 1, win 57, options [nop,nop,TS val 3589524071 ecr 4281235631], length 90

可以看到几乎每个包都有重复的条目, 包括 tcp 的三次握手及数据传输等. 所以这里就出现了几个问题：

1. tcpdump 是从哪个网卡抓到的接收的报文(eth2 还是 bond1)?
2. 为什么 web 主机的出方向的包也有重复的条目?

分析处理

有趣的是在 redis 主机上单独监听 bond1 网卡, 数据报文都是正常的, web 主机上独立监听 bond1 网卡也是正常的, 这说明 redis 主机并没有向 web 主机重复发送报文, 也说明 web 主机没有重复向 redis 主机发送报文.

对于第一个问题, 很遗憾 tcpdump 并没有类似的功能能够显示来源数据对应的网卡, 所以我们难以区别到底是 eth2 还是 bond1 网卡引起了重复报文. 第二个问题则比较奇特, 从抓出的报文来看 wen 主机重复发送请求但是 redis 主机并没有收到, 这说明重复发送可能只是 web 主机内部的原因, 同样重复接收报文可能也是 web 主机的内部原因.

我们从内核文档bonding 找到以下重复报文相关的内容

10. 小节
 For the active-backup, balance-tlb and balance-alb modes, the
promiscuous mode setting is propagated only to the active slave.
......
For the active-backup, balance-tlb and balance-alb modes, when
the active slave changes (e.g., due to a link failure), the
promiscuous setting will be propagated to the new active slave.
......
......
13.2 小节:
This is not due to an error in the bonding driver, rather, it
is a side effect of how many switches update their MAC forwarding
tables.  Initially, the switch does not associate the MAC address in
the packet with a particular switch port, and so it may send the
traffic to all ports until its MAC forwarding table is updated.  Since
the interfaces attached to the bond may occupy multiple ports on a
single switch, when the switch (temporarily) floods the traffic to all
ports, the bond device receives multiple copies of the same packet
(one per slave device).
 
    The duplicated packet behavior is switch dependent, some
switches exhibit this, and some do not.  On switches that display this
behavior, it can be induced by clearing the MAC forwarding table (on
most Cisco switches, the privileged command "clear mac address-table
dynamic" will accomplish this).

从这点看, tcpdump 仅将混杂模式传播到当前活动的网卡中, 另外在交换机进行 MAC 地址学习的时候可能会出现这种重复报文的情况, 这种情况还依赖于交换机的功能. 从这点来看内核文档的解释和我们的问题并没有关系.

由此我们继续追查别的方面, 从底向上的分析, 在 web 主机收到报文的时候, 会对整个报文进行解封装, 如下图所示为数据报文的封装和解封装过程:

从右边的解封装过程来看, 主机的 MAC 地址经过交换机的学习后不会再出现上述内核文档的现象, 而且数据经过传输肯定会先传到 web 主机的 eth2 物理网卡上, 而不是我们认为的直接到 bond1 网卡上. 我们参考文章 tcpdump-work-with-bonding-interface 了解到在 centos 5 系统中, 内核接收到数据报文之后会直接将 skb-dev 从 eth2 更新为 bond1, 最后再将报文通过 bond1 网口发送给 ptye_all, 由于这个工作模式, 直接通过 tcpdump -i eth2 是抓取不到任何包的, 因为报文数据不会经过 eth2.

但是在 linux 内核 3.16 之后, 内核作者 torvalds 修改了工作模式, skb->dev 首先为 eth2 物理网卡, 数据先通过 eth2, 经过 rx_handler 进行处理, 最后找到 bond1 网卡, 再将数据发送到 bond1 进行处理. 如下:

bond related process is moved to dev->rx_handler, Just like the bridge or openvswitch.

Packet will first be processed by ptype_all with skb->dev is eth0 and then rx_handler(bond handler for eth0,eth1). if the rx handler return RX_HANDLER_ANOTHER, the packet arrive by ptye_all again with differentskb->dev (bond0).

从这点来看, web 主机接收的数据报文会先经过 eth2, 再经过 bond1, 而发送的报文则会先经过 bond1, 再经过 eth2 网卡. 而 tcpdump 使用 -i any 选项抓包, 则意味着不管接收还是发送都会出现重复的条目. 为了验证此猜测我们同时监听 eth2 和 bond1 网卡:

在两个终端界面输入下面命令:
tcpdump -S -s 0 -n -n -i eth2 port 6380 -w eth2_6380.pcap
tcpdump -S -s 0 -n -n -i eth2 port 6380 -w bond1_6380.pcap

可以看到如下输出: eth2 抓包的数据

# tcpdump -n -n -r eth2_6380.pcap 
reading from file eth2_6380.pcap, link-type EN10MB (Ethernet)
40:59.309086 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [S], seq 275391682, win 14600, options [mss 1460,sackOK,TS val 70624316 ecr 0,nop,wscale 8], length 0
40:59.309122 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [S.], seq 969430611, ack 275391683, win 14480, options [mss 1460,sackOK,TS val 3674159462 ecr 70624316,nop,wscale 8], length 0
40:59.309137 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 1, win 58, options [nop,nop,TS val 70624316 ecr 3674159462], length 0
41:01.130610 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [P.], seq 1:7, ack 1, win 58, options [nop,nop,TS val 70626138 ecr 3674159462], length 6
41:01.130643 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [.], ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 0
41:01.130728 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [.], seq 1:1449, ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 1448
41:01.130739 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 1449, win 69, options [nop,nop,TS val 70626138 ecr 3674161283], length 0
41:01.130776 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [P.], seq 1449:2193, ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 744
41:01.130784 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 2193, win 80, options [nop,nop,TS val 70626138 ecr 3674161283], length 0
41:04.453604 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [F.], seq 7, ack 2193, win 80, options [nop,nop,TS val 70629461 ecr 3674161283], length 0
41:04.453694 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [F.], seq 2193, ack 8, win 57, options [nop,nop,TS val 3674164606 ecr 70629461], length 0
41:04.453709 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 2194, win 80, options [nop,nop,TS val 70629461 ecr 3674164606], length 0

bond1 抓包的数据:

# tcpdump -n -n -r bond1_6380.pcap 
reading from file bond1_6380.pcap, link-type EN10MB (Ethernet)
40:59.309081 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [S], seq 275391682, win 14600, options [mss 1460,sackOK,TS val 70624316 ecr 0,nop,wscale 8], length 0
40:59.309122 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [S.], seq 969430611, ack 275391683, win 14480, options [mss 1460,sackOK,TS val 3674159462 ecr 70624316,nop,wscale 8], length 0
40:59.309136 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 1, win 58, options [nop,nop,TS val 70624316 ecr 3674159462], length 0
41:01.130605 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [P.], seq 1:7, ack 1, win 58, options [nop,nop,TS val 70626138 ecr 3674159462], length 6
41:01.130643 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [.], ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 0
41:01.130728 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [.], seq 1:1449, ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 1448
41:01.130737 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 1449, win 69, options [nop,nop,TS val 70626138 ecr 3674161283], length 0
41:01.130776 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [P.], seq 1449:2193, ack 7, win 57, options [nop,nop,TS val 3674161283 ecr 70626138], length 744
41:01.130782 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 2193, win 80, options [nop,nop,TS val 70626138 ecr 3674161283], length 0
41:04.453600 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [F.], seq 7, ack 2193, win 80, options [nop,nop,TS val 70629461 ecr 3674161283], length 0
41:04.453694 IP 10.0.21.7.6380 > 10.0.21.5.42953: Flags [F.], seq 2193, ack 8, win 57, options [nop,nop,TS val 3674164606 ecr 70629461], length 0
41:04.453707 IP 10.0.21.5.42953 > 10.0.21.7.6380: Flags [.], ack 2194, win 80, options [nop,nop,TS val 70629461 ecr 3674164606], length 0

可以看到, eth2 和 bond1 抓到了同样的报文, 只是时间戳稍有不同, 这是正常的因为 redis 主机网 web 主机发的包的时间戳是固定的, 上面可以看到从 10.0.21.7 到 10.0.21.5 主机的时间戳都不变化, 而 web 主机到 redis 主机的时间戳则有一些不同, 基本都相差几微秒.

由此可以猜测出, tcpdump 使用 -i any 选项会把 eth2 和 bond1 的报文都抓取, 而两个网卡报文的时间戳有特别相近, 所以使用 wireshark 进行查看的时候会出现各种各样的提示. 以上述的截图为例进行说明:

1. tcp out of order

第一条为三次握手的第一个包, 因为是从 web 主机发出去的, 所以第一条应该是 bond1 网卡的 syn 报文, 紧跟的第二条则为 eth2 网卡的 syn 报文, 而且两个条目还相差 5 微秒, 对于 wireshark 而言第二条报文不是期待的 syn + ack, 时间戳也不一样, 所以就提示乱序. 事实上在 tcp 三次握手和四次回收的过程中是不会出现乱序的, 乱序只在传输数据报文的时候发生.

2. tcp Dup Ack

当乱序或丢包发生时,web 会收到一些 seq 号比期望大的包, web 每收到这种包就会 ack 一次期望的值提醒发送方, 于是就产生 Dup Ack, wireshark 则提示 tcp Dup Ack, 截图中则主要由于时间戳乱序引起了该提示.

3. tcp retransmission

正常情况下, 一个包丢失以及没有后续的 Dup Ack 包, 则会进行超时重传操作. 而在本文的示例中, 由于传输的数据包(P 标志)有重复的而且seq, ack 这些都一样所以 wireshark 会直接提示该包为重传的包.

总结

总体来看, 出现重复报文算是虚惊一场, 不是内核的 bug 也不是 tcpdump 的 bug, 而是 bond 的机制需要经过多次转发处理, 这也能解释为什么 redis 主机上的报文都是正常的. 如上所述, 如果在 centos 5 中抓包应该就不会出现本文的问题. 所以出现重复报文只是一种现象, 不会影响本地网卡的流量, 也不会影响业务的交互. 或许 tcpdump 会在将来修复这个不算错误的漏洞, linux 也可能换一种机制来完成数据的传输.

← → Top