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

[Paul Vlaar]

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