Re: Tracking down validation failures
On Jun 12 20009, I wrote: [...] 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. Just to expand on that a bit: the DS record in the parent zone correctly describes the KSK in the child zone, and the RRSIGs in 8.84.in-addr.arpa appear to be correct ... except that they all expired over 15 months ago! -- Chris Thompson Email: c...@cam.ac.uk ___ bind-users mailing list bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users
Re: Tracking down validation failures
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
Re: Tracking down validation failures
At 12 Jun 2009 17:50:39 +0100, Chris Thompson c...@cam.ac.uk wrote: (They don't add up to as much as the statistics-channel ValFail counter is increasing by, though.] It's not surprising: if validation attempt succeeds with one authoritative server after some validation failures with other authoritative servers, you won't see the intermediate error in query-error log messages. But these failures are still counted in ValFail. --- JINMEI, Tatuya Internet Systems Consortium, Inc. ___ bind-users mailing list bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users
Re: Tracking down validation failures
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: 11-Jun-2009 12:59:43.332 query-errors: debug 1: client 127.0.0.1#59980: query failed (SERVFAIL) for advocaat.pro/IN/SOA at query.c:4626 11-Jun-2009 12:59:43.332 query-errors: debug 2: fetch completed at resolver.c:2995 for advocaat.pro/SOA in 0.422699: failure/insecurity proof failed [domain:pro,referral:1,restart:2,qrysent:4,timeout:0,lame:0, neterr:0,badresp:0,adberr:0,findfail:0,valfail:4] It is way less noisy than the dnssec logging. Also you should see some of the logging by default in the lame-servers category (at level info) such as: Jun 11 12:59:43 tx named[1490]: error (insecurity proof failed) resolving 'advocaat.pro/SOA/IN': 192.149.63.10#53 Jun 11 12:59:43 tx named[1490]: error (insecurity proof failed) resolving 'advocaat.pro/SOA/IN': 192.149.62.10#53 Jun 11 12:59:43 tx named[1490]: error (insecurity proof failed) resolving 'advocaat.pro/SOA/IN': 192.149.64.10#53 Jun 11 12:59:43 tx named[1490]: error (insecurity proof failed) resolving 'advocaat.pro/SOA/IN': 192.149.66.10#53 (see valfail count above is 4) ___ bind-users mailing list bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users
Re: Tracking down validation failures
In message prayer.1.3.1.0906111834360.6...@hermes-2.csi.cam.ac.uk, Chris Thom pson writes: 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. The advice usually given is to log category dnssec at debug level 3, but this produces far too much data. Reducing it debug level 2, on the other hand, gives almost nothing. I do see a trickle of info-level messages: 11-Jun-2009 18:12:32.375 info: validating @15abde10: 17.62.212.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:12:32.376 info: validating @15abde10: 17.62.212.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:12:42.258 info: validating @f3e9cb8: 99.188.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:12:42.259 info: validating @f3e9cb8: 99.188.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:15:08.235 info: validating @15bed590: 97.102.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:15:08.236 info: validating @15bed590: 97.102.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:15:08.592 info: validating @15bed590: 97.102.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:15:08.593 info: validating @15bed590: 97.102.91.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:19:32.048 info: validating @8af4a40: 99.96.79.IN-ADDR.ARPA NSEC: no valid signature found 11-Jun-2009 18:19:32.049 info: validating @8af4a40: 99.96.79.IN-ADDR.ARPA NSEC: no valid signature found but it's not even obvious what the original query was in these cases. (If I could find that out I could try the same query on a quieter nameserver with more logging turned on.) There are no messages generated at this level when I force a validation failure to occur (dig soa advocaat.pro remains my favourite). Any suggestions? -- Chris Thompson Email: c...@cam.ac.uk ___ bind-users mailing list bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users Do you have RIPE's trusted-keys configured into named.conf and are they up to date? http://www.ripe.net/projects/disi/keys/ https://www.ripe.net/projects/disi/keys/ripe-ncc-dnssec-keys-new.txt Note named won't go to dlv if the answer is within a island of security identified by a trusted-key in named.conf. The data currently being returned looks good to me. This is a referral to a insecure zone. 17.62.212.IN-ADDR.ARPA. 172800 IN NS ans2.cw.net. 17.62.212.IN-ADDR.ARPA. 172800 IN NS ans1.cw.net. 17.62.212.IN-ADDR.ARPA. 7200IN NSEC170.62.212.in-addr.arpa. NS RRSIG NSEC 17.62.212.IN-ADDR.ARPA. 7200IN RRSIG NSEC 5 5 7200 20090711232326 20090611232326 34470 212.in-addr.arpa. pY89tH87GQjFm4YRAHCx8wY0R14fjN0Qb+wwGCDbJjAC1zezYUT+ltZN J/5akqXTY7vQ/h7u/t8gz7qf1Q1mSE0xngF/3amoZaNHpPNT9BGOeF89 kC4ucFI2e/MnU9lvmEJHVT5Ma0eJ4LRgFlGaeUmSMaPjRBxpOJpNGP/x O/jxf84LTsANHVBew8a7BI9tmg0ozppN ;; Received 338 bytes from 2001:660:3006:1::1:1#53(NS3.NIC.FR) in 548 ms % date -u +%Y%m%d%H%M%S 20090612011526 % Validation interval ok. 20090711232326 20090612011526 20090611232326 No DS in list of types that exist at 17.62.212.IN-ADDR.ARPA. Signed with key 34470. ; DiG 9.3.6-P1 +dnssec +multi dnskey 212.IN-ADDR.ARPA ;; global options: printcmd ;; Got answer: ;; -HEADER- opcode: QUERY, status: NOERROR, id: 4082 ;; flags: qr rd ra ad; QUERY: 1, ANSWER: 7, AUTHORITY: 0, ADDITIONAL: 1 ;; OPT PSEUDOSECTION: ; EDNS: version: 0, flags: do; udp: 4096 ;; QUESTION SECTION: ;212.IN-ADDR.ARPA. IN DNSKEY ;; ANSWER SECTION: 212.IN-ADDR.ARPA. 2663 IN DNSKEY 256 3 5 ( AwEAAbW5cAVaimsuasYP4uwC/Id+/MJce+q+9FwBz4iO bkPa5YNFz7qeV+y8BjKI/7nQ/4fh/Xd7tp+5eYT47GEx ALl4GBGKoW22k/IpD1nqNuGs4BYvuG/kTfhtTEWyfMbB 20M17W0vPbHmhLDbdGO0qg1HPQZ0gXYFCofu9OX86OGL V+YFEJ+NeWiNHg91xq1svv0sehJp7w== ) ; key id = 34470 212.IN-ADDR.ARPA. 2663 IN DNSKEY 256 3 5 ( AwEAAd2guc91r8v8RRtTcKLIGWPbLNi9HuAmcxNwW+7N 4KCPxci7GPqgqD/m88qbBDYdm1XMLHSV+lZ+DbifbFpw cIu1+vt4dEGB7O9bCuZwQG89HN7IpTRhZQXH3P8O5eCt 7UJEOm4BWfRD4DKYyuOHGpdWTqyzY0TKGWECXW00X1rQ t4MZmBl8Z4r8kLN+X4jWXoQzpygfXw== ) ; key id = 12075 212.IN-ADDR.ARPA. 2663 IN DNSKEY 257 3 5 (
