[dnscap-users] dnscap 1.2.0 dropping packets vs version 20160205?

[Wessels, Duane]

Hi Paul,

Nice to hear from you :-)

I ran a few quick tests on my servers and here is what I found.  

First I used a simple program to just send 1,000,000 DNS queries as fast as it could (takes about 2 seconds) from one machine to another on the same LAN. These are just identical UDP queries, not real traffic. The receiving machine where dnscap runs is RHEL 7.

I ran dnscap-20160205 by itself:

$ sudo ./dnscap -f -6 -m q -s i -i ens1f0 -t 300 -L 4095 -T -w /disk2/tmp/dnscap-old
$ tcpdump -n -r dnscap-old.20161130.005918.572896 | wc -l
reading from file dnscap-old.20161130.005918.572896, link-type RAW (Raw IP)
 752453

And then the 1.2.0 version:

$ sudo ./dnscap -f -6 -m q -s i -i ens1f0 -t 300 -L 4095 -T -w /disk2/tmp/dnscap-new
$ tcpdump -n -r dnscap-new.20161130.010121.183385 | wc -l
reading from file dnscap-new.20161130.010121.183385, link-type RAW (Raw IP)
 748598

So they are about the same.

Note: We're obviously not capturing all 1,000,000 packets.  About 25 are lost either in transmission or by the kernel.

Next I ran the two at the same time in two different windows:

$ sudo ./dnscap -f -6 -m q -s i -i ens1f0 -t 300 -L 4095 -T -w /disk2/tmp/dnscap-old-parallel
$ sudo ./dnscap -f -6 -m q -s i -i ens1f0 -t 300 -L 4095 -T -w /disk2/tmp/dnscap-new-parallel

$ tcpdump -n -r dnscap-old-parallel.20161130.010315.304653 | wc -l
reading from file dnscap-old-parallel.20161130.010315.304653, link-type RAW (Raw IP)
 608956
$ tcpdump -n -r dnscap-new-parallel.20161130.010315.304653 | wc -l
reading from file dnscap-new-parallel.20161130.010315.304653, link-type RAW (Raw IP)
 609134

Lower but still nearly the same.

Out of curiosity I compared it to a vanilla tcpdump capture:

$ sudo tcpdump -n -i ens1f0 -w /disk2/tmp/tcpdump port domain
$ tcpdump -n -r /disk2/tmp/tcpdump |wc -l
reading from file /disk2/tmp/tcpdump, link-type EN10MB (Ethernet)
 881238

DW




> On Nov 29, 2016, at 12:51 PM, Paul Vlaar <paul at flairlab.nl> wrote:
> 
> I just noticed that when I capture using version 1.2.0 and the old
> 20160205 version, I get quite a different number of queries recorded.
> 
> For example, I ran the following with both versions simultaneously on
> the same host at the same time:
> 
> # ./dnscap-1.2.0 -b -f -6 -m q -s i -i eth2 -t 300 -L 4095 -T -w
> /tmp/dnscap-1.2.0
> 
> # ./dnscap-20160205 -b -f -6 -m q -s i -i eth2 -t 300 -L 4095 -T -w
> /tmp/dnscap-20160205
> 
> Then I do the following:
> 
> $ ./dnscap-1.2.0 -N -m q -s i -6 -g -r
> /tmp/dnscap-20160205.20161129.200000.001788 2>&1 | grep "2016-11-29" | wc -l
> 68431
> 
> $ ./dnscap-1.2.0 -N -m q -s i -6 -g -r
> /tmp/dnscap-1.2.0.20161129.200000.292235 2>&1 | grep "2016-11-29" | wc -l
> 51728
> 
> That's about 25% missing, somehow, can this really be? Let's look at the
> actual output and compare around the same timestamp:
> 
> $ ./dnscap-1.2.0 -N -m q -s i -6 -g -r
> /tmp/dnscap-20160205.20161129.200000.001788
> 
> [95] 2016-11-29 20:00:59.762965 [#14267
> dnscap-20160205.20161129.200000.001788 4095] \
>        [removed].46940 [removed].53  \
>        dns QUERY,NOERROR,56348 \
>        1 www.thedogguy.info,IN,A 0 0 \
>        1 .,4096,4096,32768,edns0[len=0,UDP=4096,ver=0,rcode=0,DO=1,z=0] \
> 
> [97] 2016-11-29 20:00:59.767635 [#14268
> dnscap-20160205.20161129.200000.001788 4095] \
>        [removed].63684 [removed].53  \
>        dns QUERY,NOERROR,43970 \
>        1 thecreperiecafe.info,IN,AAAA 0 0 \
>        1 .,4096,4096,32768,edns0[len=0,UDP=4096,ver=0,rcode=0,DO=1,z=0] \
> 
> [74] 2016-11-29 20:00:59.780750 [#14269
> dnscap-20160205.20161129.200000.001788 4095] \
>        [removed].42341 [removed].53  \
>        dns QUERY,NOERROR,51967 \
>        1 tHEFOODWorKS.inFO,IN,A 0 0 \
>        1 .,4096,4096,32768,edns0[len=0,UDP=4096,ver=0,rcode=0,DO=1,z=0] \
> 
> [68] 2016-11-29 20:00:59.785418 [#14270
> dnscap-20160205.20161129.200000.001788 4095] \
>        [removed].55944 [removed].53  \
>        dns QUERY,NOERROR,47736 \
>        1 WWw.eLNoSSHoppInG.InfO,IN,A 0 0 0
> 
> 
> So that's 4 consecutive queries around 20:00:59.7
> 
> Now let's look at version 1.2.0:
> 
> $ ./dnscap-1.2.0 -N -m q -s i -6 -g -r
> /tmp/dnscap-1.2.0.20161129.200000.292235
> 
> [95] 2016-11-29 20:00:59.762965 [#11268
> dnscap-1.2.0.20161129.200000.292235 4095] \
>        [removed].46940 [removed].53  \
>        dns QUERY,NOERROR,56348 \
>        1 www.thedogguy.info,IN,A 0 0 \
>        1 .,4096,4096,32768,edns0[len=0,UDP=4096,ver=0,rcode=0,DO=1,z=0] \
> 
> [97] 2016-11-29 20:00:59.767635 [#11269
> dnscap-1.2.0.20161129.200000.292235 4095] \
>        [removed].63684 [removed].53  \
>        dns QUERY,NOERROR,43970 \
>        1 thecreperiecafe.info,IN,AAAA 0 0 \
>        1 .,4096,4096,32768,edns0[len=0,UDP=4096,ver=0,rcode=0,DO=1,z=0] \
> 
> [62] 2016-11-29 20:01:00.405206 [#11270
> dnscap-1.2.0.20161129.200000.292235 4095] \
>        [removed].43899 [removed].53  \
>        dns QUERY,NOERROR,7779 \
>        1 nS3.MazUrEK.Info,IN,A 0 0 0
> [58] 2016-11-29 20:01:00.408672 [#11271
> dnscap-1.2.0.20161129.200000.292235 4095] \
>        [removed].47944 [removed].53  \
>        dns QUERY,NOERROR,47926 \
>        1 mEgApIc.InfO,IN,A 0 0 0
> 
> 
> Aha, so here's only 2 queries around 20:00:59.7, and then a whole bunch
> are skipped and we end up at 20:01:00.4 all of a sudden. No wonder 25%
> is missing in my initial count.
> 
> I haven't looked in the source yet to see what the problem might be, but
> maybe anyone here has noticed a similar thing. It may also be my system
> somehow, but I doubt it, since everything else is the same.
> 
> Thanks,
> 
> 	~paul
> 
> 
> -- 
> Paul Vlaar - FlairLab
> Internet engineering, consultancy
> Dutch Chamber of Commerce 63553104
> _______________________________________________
> dnscap-users mailing list
> dnscap-users at lists.dns-oarc.net
> https://lists.dns-oarc.net/mailman/listinfo/dnscap-users