Packetbeat: Something wired with "WARN Time in pcap went backwards"

Elastic Stack Beats
1

when analyzing pcap files, I always find outputs as follow:

➜  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

after some source codes digging, I find something I can not understand.

func (sniffer *SnifferSetup) Run() error {
                ...
		if sniffer.config.File != "" {
			if lastPktTime != nil && !sniffer.config.TopSpeed { 
				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
			if !sniffer.config.TopSpeed {
				ci.Timestamp = time.Now() // overwrite what we get from the pcap
			}
		}

According to the code, if -t option not set, every packet in the pcap file will use current system time as timestamp. However, when computing time difference between two successive packets, the latter one use its real timestamp which is set on capturing. I think it is the root case why "backwards" happends, and I think it is a bug.

right now, when reading packets from pcap files, I always use -t option to avoid annoying "backwards" output.

Can someone tell me if I misunderstanding anything? Tks in advance.

2

Have you checked your pcap?

Cleaning up the sample code a little it becomes:

	if sniffer.config.File != "" {
		if !sniffer.config.TopSpeed {
			pktTime := ci.Timestamp
			if lastPktTime != nil {
				sleep := pktTime.Sub(*lastPktTime)
				if sleep > 0 {
					time.Sleep(sleep)
				} else {
					logp.Warn("Time in pcap went backwards: %d", sleep)
				}
			}
			lastPktTime = &pktTime

			// overwrite what we get from the pcap
			ci.Timestamp = time.Now()
		}
	}

you're right, if topspeed is disabled, the system time is assigned to the packet. But the system time is assigned after the sleep. That is the sleep instruction indeed uses the delta timestamps between packets as available in the pcap file. This is done, so that replaying the pcap will be about as fast as the original traffic being recorded. That is, the warning seems to be correct to me.

3

yes, I get it, according to your advice, I checked my pcap file, the timestamps in it seem reasonable to me.

some snapshots here:

  • Seconds since beginning of capture

  • Date and time of day

From the snapshots, I find the reason why there are tens of thousands of "Time in pcap went backwards" warnings. It is the "[TCP Retransmission]" that results in this issue.

In my test, I get 15563 times of this warning info.

root@vagrant-ubuntu-trusty:/go/src/github.com/elastic/beats/packetbeat# ./packetbeat -c ./packetbeat.yml -e -I redis_xxx.pcap -E packetbeat.protocols.redis.ports=7101 2>&1 |grep "WARN Time in pcap went backwards" |wc -l
15563

The conclusion is

  • the warning is correct.
  • network situation is the real problem.

tks again.