[Bug] Packets slowly drift further and further behind when they should be sent

[davecraig]

Using a simple tcpreplay e.g.

sudo src/tcpreplay -K test.pcap

If I record another PCAP of the playout, the packets in the playout happen later and later compared to the original test.pcap. The reason is that the timing is all done using deltas between packets and errors in timing accumulate. This has a huge impact on playback of time sensitive PCAPs e.g. UDP video containing PCR timestamps.

I have a suggested patch for this which switches to comparing times since the first packet was sent.

[fklassen]

I have not seen this before. I need more context. Please fill in the bug report.

Describe the bug
A clear and concise description of what the bug is.

To Reproduce
Steps to reproduce the behavior:
1.
2.
3.
4.

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

System (please complete the following information):

• OS: [e.g. macOS]
• OS version
• Tcpreplay Version [e.g. 4.3.2]

Additional context
Add any other context about the problem here.

[davecraig]

tcpreplay slowly loses time meaning that packets get more and more delayed as the playout continues. An easy way to reproduce this is:

1. Create a PCAP e.g. randpkt -b 1400 -t udp -c 100000 test.pcap
2. Playout the pcap with tcpreplay: sudo tcpreplay -K --multiplier=10000 test.pcap
3. Note how long it takes (Actual: 100000 packets (71786397 bytes) sent in 10.10 seconds in my case) and then double check tcpdump the data to see how accurately the packets were sent out.

randpkt creates 1 packet each second, so the playout is done at 10000 speed which gives around ~56Mbps. In my test the tcpdump looked like this:

No.	Time	Source	Destination	Protocol	Length	Info	Absolute time
26	*REF*	208.21.2.184	10.1.1.99	UDP	1055	9587 → 206 [BAD UDP LENGTH 33828 > IP PAYLOAD LENGTH] Len=33820	26
27	0.000009	208.21.2.184	10.1.1.99	UDP	795	4171 → 62106 [BAD UDP LENGTH 59293 > IP PAYLOAD LENGTH] Len=59285	27
28	0.000111	208.21.2.184	10.1.1.99	UDP	229	54603 → 27660 [BAD UDP LENGTH 38445 > IP PAYLOAD LENGTH] Len=38437	28
29	0.000212	208.21.2.184	10.1.1.99	UDP	608	43098 → 61502 [BAD UDP LENGTH 6855 > IP PAYLOAD LENGTH] Len=6847	29
30	0.000314	208.21.2.184	10.1.1.99	UDP	817	23549 → 601 [BAD UDP LENGTH 64375 > IP PAYLOAD LENGTH] Len=64367	30
31	0.000417	208.21.2.184	10.1.1.99	UDP	185	5434 → 22401 [BAD UDP LENGTH 9587 > IP PAYLOAD LENGTH] Len=9579	31
32	0.000519	208.21.2.184	10.1.1.99	UDP	123	13265 → 41894 [BAD UDP LENGTH 60500 > IP PAYLOAD LENGTH] Len=60492	32
33	0.000621	208.21.2.184	10.1.1.99	UDP	713	62853 → 21742 [BAD UDP LENGTH 35549 > IP PAYLOAD LENGTH] Len=35541	33
34	0.000722	208.21.2.184	10.1.1.99	UDP	508	36000 → 61414 [BAD UDP LENGTH 3018 > IP PAYLOAD LENGTH] Len=3010	

The timestamps for the packets gets behind by a couple of microseconds for each packet. After 60 packets it's behind by 100 microseconds. The Actual time reported after playback being over 10 seconds accurately reflects the drift.
To check that the hardware isn't a problem I switched to

tcpreplay -K --pps=10000 test.pcap

and the playback took 9.99 seconds each time

I had assumed that the reference to tcpreplay in this academic paper referred to this same issue, though it's hard to say https://core.ac.uk/download/pdf/33506736.pdf

"We assessed the most commonly-used such tool, tcpreplay [3], and showed it to suffer from cumulative timing drift, as well
as timing inaccuracy."

OS: Debian linux
OS version: Linux version 4.19.0-14-amd64 ([email protected]) (gcc version 8.3.0 (Debian 8.3.0-6)) #1 SMP Debian 4.19.171-2 (2021-01-30)
Tcpreplay Version: 4.3.1

Note that I found this replaying real captures which contained video PCR data, it's just randpkt generated files are easier for reproduction.

[fklassen]

Thanks for the bug report.

Scheduled for next release.

[fklassen]

Verification of PR #631 ...

Played back a basic ping file and compared expected vs. actual debug log results. They match:

• expected:

• actual:

DEBUG1 in sendpacket.c:sendpacket_open_pf() line 888: sendpacket: using PF_PACKET
DEBUG2 in send_packets.c:send_packets() line 372: packet 1 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=2
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #1
DEBUG2 in send_packets.c:send_packets() line 372: packet 2 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=2
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 35685000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #2
DEBUG2 in send_packets.c:send_packets() line 372: packet 3 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 963936000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #3
DEBUG2 in send_packets.c:send_packets() line 372: packet 4 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 56380000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #4
DEBUG2 in send_packets.c:send_packets() line 372: packet 5 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 944147000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #5
DEBUG2 in send_packets.c:send_packets() line 372: packet 6 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 37219000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #6
DEBUG2 in send_packets.c:send_packets() line 372: packet 7 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 963140000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #7
DEBUG2 in send_packets.c:send_packets() line 372: packet 8 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 36757000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #8
DEBUG2 in send_packets.c:send_packets() line 372: packet 9 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 964049000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #9
DEBUG2 in send_packets.c:send_packets() line 372: packet 10 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 45953000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #10
DEBUG2 in send_packets.c:send_packets() line 372: packet 11 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 954654000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #11
DEBUG2 in send_packets.c:send_packets() line 372: packet 12 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 49684000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #12
DEBUG2 in send_packets.c:send_packets() line 372: packet 13 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 951102000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #13
DEBUG2 in send_packets.c:send_packets() line 372: packet 14 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 48824000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #14
DEBUG2 in send_packets.c:send_packets() line 372: packet 15 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 951042000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #15
DEBUG2 in send_packets.c:send_packets() line 372: packet 16 caplen 98
DEBUG2 in flows.c:hash_put_data() line 150: flow type=3
DEBUG2 in send_packets.c:tcpr_sleep() line 1133: Sleeping:                   0s 37878000nsec
DEBUG2 in send_packets.c:send_packets() line 484: Sending packet #16
DEBUG1 in utils.c:_our_safe_pcap_next() line 151: No data found in packet
Actual: 16 packets (1568 bytes) sent in 7.04 seconds
Rated: 222.6 Bps, 0.001 Mbps, 2.27 pps
Flows: 2 flows, 0.28 fps, 16 flow packets, 0 non-flow
Statistics for network device: ens33
	Successful packets:        16
	Failed packets:            0
	Truncated packets:         0
	Retried packets (ENOBUFS): 0
	Retried packets (EAGAIN):  0

[fklassen]

Fixed in PR #631 and #645