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.
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.
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
Apache, Apache Lucene, Apache Hadoop, Hadoop, HDFS and the yellow elephant
logo are trademarks of the
Apache Software Foundation
in the United States and/or other countries.