Tracking down validation failures

Fri Jun 12 16:50:39 UTC 2009

On Jun 11 2009, Jeremy C. Reed wrote:

>On Thu, 11 Jun 2009, Chris Thompson wrote:
>
>> We have recently turned on DNSSEC validation (using dlv.isc.org) in our
>> main university-wide recursive nameservers, which are running BIND 9.6.1rc1.
>> 
>> No-one is actually complaining, but the counts I am seeing for "ValFail"
>> on the statistics channel are quite a bit higher than we were seeing
>> during testing, running at 0.2% - 0.4% of "ValAttempt" (but the counter
>> increases in bursts), and I would be happier knowing what they were
>> coming from.
>
>Have a look at the new (experimental) query-errors category.  For example:
[...]
>It is way less noisy than the dnssec logging.

This was a good suggestion - thank you. I have tried logging query-errors
at debug level 4, and some of the entries do have non-zero valfail counts.
(They don't add up to as much as the statistics-channel "ValFail" counter
is increasing by, though.] Here is a half-hour sample from one of the
nameservers:

12-Jun-2009 16:27:59.583 debug 4: fetch completed at resolver.c:4046
 for 38.130.244.88.IN-ADDR.ARPA/PTR in 0.678061: success/not insecure
 [domain:88.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]
12-Jun-2009 16:35:00.415 debug 4: fetch completed at resolver.c:4046
 for 102.136.103.91.IN-ADDR.ARPA/PTR in 1.045085: success/not insecure
 [domain:91.in-addr.arpa,referral:0,restart:1,qrysent:3,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:2]
12-Jun-2009 16:36:31.380 debug 2: fetch completed at resolver.c:2891
 for 130.40.8.84.in-addr.arpa/PTR in 3.500594: failure/no valid DS
 [domain:40.8.84.in-addr.arpa,referral:1,restart:2,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:2]
12-Jun-2009 16:36:38.606 debug 2: fetch completed at resolver.c:2891
 for 130.40.8.84.in-addr.arpa/PTR in 3.689695: failure/no valid ds
 [domain:40.8.84.in-addr.arpa,referral:0,restart:2,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:2]
12-Jun-2009 16:36:58.459 debug 4: fetch completed at resolver.c:4046
 for 55.106.0.89.IN-ADDR.ARPA/PTR in 0.642334: success/not insecure
 [domain:89.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]
12-Jun-2009 16:41:53.588 debug 2: fetch completed at resolver.c:2891
 for 130.40.8.84.in-addr.arpa/PTR in 4.228979: failure/no valid DS
 [domain:40.8.84.in-addr.arpa,referral:0,restart:2,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:2]
12-Jun-2009 16:43:34.731 debug 4: fetch completed at resolver.c:4046
 for 172.164.22.213.IN-ADDR.ARPA/PTR in 0.489031: success/not insecure
 [domain:213.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]
12-Jun-2009 16:43:55.521 debug 2: fetch completed at resolver.c:2891
 for 40.8.84.in-addr.arpa/DS in 3.186479: failure/no valid RRSIG
 [domain:8.84.in-addr.arpa,referral:1,restart:2,qrysent:4,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:4]
12-Jun-2009 16:47:36.840 debug 4: fetch completed at resolver.c:4046
 for 157.14.110.87.IN-ADDR.ARPA/PTR in 0.551489: success/not insecure
 [domain:87.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]
12-Jun-2009 16:47:59.038 debug 2: fetch completed at resolver.c:2891
 for 40.8.84.in-addr.arpa/DS in 1.243316: failure/no valid RRSIG
 [domain:8.84.in-addr.arpa,referral:1,restart:2,qrysent:4,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:4]
12-Jun-2009 16:48:08.100 debug 4: fetch completed at resolver.c:4046
 for 126.85.252.77.IN-ADDR.ARPA/PTR in 0.635810: success/not insecure
 [domain:77.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]
12-Jun-2009 16:53:01.580 debug 2: fetch completed at resolver.c:2891
 for 52.7.8.84.in-addr.arpa/PTR in 10.775506: failure/no valid DS
 [domain:8.84.in-addr.arpa,referral:0,restart:2,qrysent:4,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:4]
12-Jun-2009 16:53:19.150 debug 2: fetch completed at resolver.c:2891
 for 52.7.8.84.in-addr.arpa/PTR in 12.530152: failure/no valid DS
 [domain:8.84.in-addr.arpa,referral:0,restart:2,qrysent:4,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:4]
12-Jun-2009 16:53:35.240 debug 2: fetch completed at resolver.c:2891
 for 52.7.8.84.in-addr.arpa/PTR in 11.088051: failure/no valid DS
 [domain:8.84.in-addr.arpa,referral:0,restart:2,qrysent:4,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:4]
12-Jun-2009 16:53:51.844 debug 4: fetch completed at resolver.c:4046
 for 134.240.154.88.IN-ADDR.ARPA/PTR in 0.643090: success/not insecure
 [domain:88.in-addr.arpa,referral:0,restart:1,qrysent:2,timeout:0,
 lame:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1]

The debug level 2 messages, which correspond to SERVFAILs, are all
associated with "8.84.in-addr.arpa", and it does seem that something
is wrong with the (signed) delegation of that from "84.in-addr.arpa".
I can reproduce the SERVFAIL effect on other validating nameservers.

But I don't understand the debug level 4 ones at all. There doesn't
seem to be anything wrong with these reverse lookups when attempted
on other (or even the same) nameservers.

Mark Andrews asked

> Do you have RIPE's trusted-keys configured into named.conf and are
> they up to date?

No, the only trusted-key configured is that for for dlv.isc.org
(which imports the keys from the RIPE-NCC TAR, of course).

-- 
Chris Thompson
Email: cet1 at cam.ac.uk