TCP Replay Packet Count

Hi,

I’m testing our Zeek version in use by replaying a pcap and checking the logs.
Let me apologise if the below seems obvious and I have missed something in my ignorance.

The packet count, gaps and several other metrics in the resulting logs and hence results are inconsistent, only by a tiny amount but still nonetheless inconsistent.

I’m testing on:

- CentOS7 7.9.2009 in a Vagrant KVM with 32 cores and 8GB RAM

- host is running Arch Linux on AMD 5950X, 64GB RAM, NVMe storage, Asus mobo, no load whilst testing

- /opt/zeek/bin/zeek version 4.0.3

- tcpreplay version: 4.3.4 (build git:v4.3.4)

- dummy0 interface `ip a l dummy0`:
  4: dummy0: <BROADCAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
  qlen 1000
    link/ether 1e:e9:98:b9:43:93 brd ff:ff:ff:ff:ff:ff

- disabled ipv6 on said interface with `echo "1" >/proc/sys/net/ipv6/conf/dummy0/disable_ipv6`

The following run from cron each minute produces consistent results as far as `wc -l *.log` and `du -chs *.log` goes (no interface):

#!/bin/bash
tmpdir="$(mktemp -d -p read XXXXXX)"
cd "$tmpdir"
/opt/zeek/bin/zeek -r ../../smallFlows.pcap
exit 0

The following run from cron every ten minutes produces inconsistent results (via interface):

#!/bin/bash
tmpdir="$(mktemp -d -p interface XXXXXX)"
cd "$tmpdir"
sudo /opt/zeek/bin/zeek -i dummy0 -f "not ip6 and not icmp6" &
sudo tcpreplay -i dummy0 ../../smallFlows.pcap >stdout.log # Takes about 300s.
sleep 60 # I noticed fewer packets received if killing the zeek process immediately.
sudo killall /opt/zeek/bin/zeek
exit 0

I looked at reporter.log:

cat */reporter.log | grep -oP "Reporter.*dummy0”:
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14259 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14260 packets received on interface dummy0
Reporter::INFO 14259 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0
Reporter::INFO 14261 packets received on interface dummy0

I created a tcpreplay stdout.log which never misses a beat:

cat */stdout.log | grep “Actual":
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds
Actual: 14261 packets (9216531 bytes) sent in 298.50 seconds

Running the same pcap in zeek proper (`zeekctl install, zeekctl check, zeekctl start`) and using libmaxmind and various other scripts and doing a `zeekctl stop` to rotate the logs is shown below. Repeated several times and logs stored in separate dirs. I have aggregated the results and inserted the headers.

zcat */2021-07-23/capture_loss* | grep "worker-1” (I read in the docs that gaps are problematic?):
#fields ts ts_delta peer gaps acks percent_lost
#types time interval string count count double
1627078238.491158 60.000603 worker-1 26 819 3.174603
1627078532.146935 293.655777 worker-1 24 3054 0.785855
1627079858.811693 60.000910 worker-1 25 815 3.067485
1627080152.620562 293.808869 worker-1 25 3058 0.817528
1627057458.150403 60.000275 worker-1 26 819 3.174603
1627057751.769200 293.618797 worker-1 24 3054 0.785855
1627058720.092130 60.000455 worker-1 26 820 3.170732
1627059013.597325 293.505195 worker-1 24 3053 0.786112
1627061055.513645 60.001085 worker-1 26 820 3.170732
1627061349.049882 293.536237 worker-1 24 3053 0.786112
1627061676.994016 60.001080 worker-1 26 820 3.170732
1627061970.581191 293.587175 worker-1 24 3053 0.786112
1627063588.951576 60.000306 worker-1 26 911 2.854007
1627063876.630828 287.679252 worker-1 24 2959 0.811085
1627067578.141685 60.000907 worker-1 26 819 3.174603
1627067871.772385 293.630700 worker-1 24 3054 0.785855
1627076816.253070 60.000343 worker-1 26 911 2.854007
1627077103.880273 287.627203 worker-1 24 2959 0.811085

zcat */2021-07-23/stats.* | grep -P "\s+manager\s\d+”
#fields ts peer mem pkts_proc bytes_recv pkts_dropped pkts_link pkt_lag events_proc events_queued active_tcp_conns active_udp_conns active_icmp_conns tcp_conns udp_conns icmp_conns timers active_timers files active_files dns_requests active_dns_requests reassem_tcp_size reassem_file_sizereassem_frag_size reassem_unknown_size
#types time string count count count count count interval count count count count count count count count count count count count count count count count count count
1627078475.686365 manager 85 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627078535.395661 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627080096.154831 manager 86 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627080155.984921 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627057695.243300 manager 85 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627057755.157963 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627058957.119362 manager 88 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627059016.798654 manager 88 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627061292.661099 manager 86 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627061352.473613 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627061914.258265 manager 85 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627061974.030343 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627063826.200864 manager 85 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627063880.012135 manager 85 0 0 - - - 159 162 0 0 0 0 00351 0 0 0 0 0 0 0 0 0
1627067815.305935 manager 86 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627067875.080940 manager 86 0 0 - - - 164 166 0 0 0 0 00363 0 0 0 0 0 0 0 0 0
1627077053.434149 manager 86 0 0 - - - 822 369 0 0 0 0 001794 63 0 0 0 0 0 0 0 0
1627077107.243627 manager 86 0 0 - - - 159 162 0 0 0 0 00351 0 0 0 0 0 0 0 0 0

zcat */2021-07-23/reporter.* | grep “dropped"
#fields ts level message location
#types time enum string string
1627078532.146935 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627080152.620562 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627057751.769200 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627059013.597325 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627061349.049882 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627061970.581191 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627063876.630828 Reporter::INFO 13902 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627067871.772385 Reporter::INFO 13939 packets received on interface dummy0, 0 (0.00%) dropped (empty)
1627077103.880273 Reporter::INFO 13902 packets received on interface dummy0, 0 (0.00%) dropped (empty)

Thank you.

You are giving zeek zero time to start before starting tcpreplay.
That is likely the cause of the packet count discrepancy.

Hi,

Thank you!

Yes, that took care of it.

> The following run from cron every ten minutes produces inconsistent results (via interface):
>
> #!/bin/bash
> tmpdir="$(mktemp -d -p interface XXXXXX)"
> cd "$tmpdir"
> sudo /opt/zeek/bin/zeek -i dummy0 -f "not ip6 and not icmp6" &
> sudo tcpreplay -i dummy0 ../../smallFlows.pcap >stdout.log # Takes about 300s.

You are giving zeek zero time to start before starting tcpreplay.
That is likely the cause of the packet count discrepancy.

      Wouldn't starting tcpdump first replicate real traffic? i.e.
would it be better to have tcpdump running first and then unleash
zeek?