【原创】packetbeat 之“WARN Time in pcap went backwards: 0”警告问题

问题描述

在使用 packetbeat 进行数据包分析过程中，输出了以下几种数值：

➜  packetbeat git:(master) ✗ ./packetbeat -c ./packetbeat.yml -e -I redis_xxxx.pcap 2>&1 |grep "pcap went backwards"
...
2017/01/11 06:57:47.091832 sniffer.go:365: WARN Time in pcap went backwards: -2000
...
2017/01/11 06:57:47.189023 sniffer.go:365: WARN Time in pcap went backwards: -1000
...
2017/01/11 06:57:47.189238 sniffer.go:365: WARN Time in pcap went backwards: 0

源码分析

在 sniffer.go 中，找到如下代码

func (sniffer *SnifferSetup) Run() error {
        ...
		if sniffer.config.File != "" {  // 如果是读取的 pcap 文件
			if lastPktTime != nil && !sniffer.config.TopSpeed { // TopSpeed 对应 -t 选项
		        // 计算前后两个数据包的时间戳之差
				sleep := ci.Timestamp.Sub(*lastPktTime)
				if sleep > 0 {
					time.Sleep(sleep)
				} else {
				    // 发现时间戳有“回退”
					logp.Warn("Time in pcap went backwards: %d",sleep)
				}
			}
			_lastPktTime := ci.Timestamp
			lastPktTime = &_lastPktTime
			// 若没有设置 -t 选项，则使用当前系统时间作为包的时间戳
			if !sniffer.config.TopSpeed {
				ci.Timestamp = time.Now() // overwrite what we get from the pcap
			}
		}
		...
}

问题原因

相邻两个数据包之间的时间差，是基于包捕获时的时间戳计算得到的；当存在大量 TCP 重传情况时（如下图），则会出现时间戳相同的情况；当有乱序发生时，则会出现时间戳差值为负的情况；

该问题与是否使用 -t 选项没有直接关系；

解决办法

可以通过设置 -t 参数绕过此问题，因为此时不会输出相应的打印内容；

补充试验

使用 -t 选项的情况：

...
2017/01/11 07:19:05.673469 logp.go:246: INFO Uptime: 523.788161ms

未使用 -t 选项的情况：

...
2017/01/11 07:20:27.991096 logp.go:246: INFO Uptime: 14.847278439s

经确认，使用 -t 选项的目的在于能够准确的按照包内容进行数据重放（包括时间延迟）；

其他

在官方论坛上的讨论；