[Pdns-users] Very odd negative cache behaviour for world-gen.g.aaplimg.com

Tue Oct 31 14:40:54 UTC 2017

Hi All

We see that the RR for world-gen.g.aaplimg.com get frequently into the negative cache on all out pdns recursors.

I bade a trace of the lookups and get the following:

Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 2 [187716/1] question for 'world-gen.g.aaplimg.com|A' from 2001:8e0:40:2:dead:beef:0:208
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Wants DNSSEC processing in query for A
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Looking for CNAME cache hit of 'world-gen.g.aaplimg.com|CNAME'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: No CNAME cache hit of 'world-gen.g.aaplimg.com|CNAME' found
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Entire name 'world-gen.g.aaplimg.com' or type was negatively cached, but entry expired
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: No cache hit for 'world-gen.g.aaplimg.com|A', trying to find an appropriate NS record
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Checking if we have NS in cache for 'world-gen.g.aaplimg.com'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: no valid/useful NS in cache for 'world-gen.g.aaplimg.com'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Checking if we have NS in cache for 'g.aaplimg.com'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: NS (with ip, or non-glue) in cache for 'g.aaplimg.com' -> 'a.gslb.aaplimg.com'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: within bailiwick: 0, not in cache / did not look at cache
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: NS (with ip, or non-glue) in cache for 'g.aaplimg.com' -> 'b.gslb.aaplimg.com'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: within bailiwick: 0, not in cache / did not look at cache
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: We have NS in cache for 'g.aaplimg.com' (flawedNSSet=0)
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Cache consultations done, have 2 NS to contact
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com.: Nameservers: a.gslb.aaplimg.com.(4.34ms), b.gslb.aaplimg.com.(4.74ms)
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Trying to resolve NS 'a.gslb.aaplimg.com' (1/2)
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716]    a.gslb.aaplimg.com: Wants DNSSEC processing in query for A
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716]    a.gslb.aaplimg.com: Looking for CNAME cache hit of 'a.gslb.aaplimg.com|CNAME'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716]    a.gslb.aaplimg.com: No CNAME cache hit of 'a.gslb.aaplimg.com|CNAME' found
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716]    a.gslb.aaplimg.com: Found cache hit for A: 17.253.201.8[ttl=84826]
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Resolved 'g.aaplimg.com' NS a.gslb.aaplimg.com to: 17.253.201.8
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Trying IP 17.253.201.8:53, asking 'world-gen.g.aaplimg.com|A'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: Got 3 answers from a.gslb.aaplimg.com (17.253.201.8), rcode=0 (No Error), aa=1, in 13ms
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: accept answer 'world-gen.g.aaplimg.com|A|17.253.53.208' from 'g.aaplimg.com'
nameservers? 1 YES!
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: accept answer 'world-gen.g.aaplimg.com|A|17.253.53.210' from 'g.aaplimg.com'
nameservers? 1 YES!
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: OPT answer '.' from 'g.aaplimg.com' nameservers
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: determining status after receiving this packet
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: answer is in: resolved to '17.253.53.208|A'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: answer is in: resolved to '17.253.53.210|A'
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 [187716] world-gen.g.aaplimg.com: status=got results, this level of recursion done
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 Starting validation of answer to world-gen.g.aaplimg.com|A for [2001:8e0:40:2:dead:beef:0:208]:47810
Oct 31 15:14:24 ac-rns1 pdns_recursor[20365]: Oct 31 15:14:24 Answer to world-gen.g.aaplimg.com|A for [2001:8e0:40:2:dead:beef:0:208]:47810 validates as Insecure

We get a valid answer from this request!

Then after the ttl expires:

Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 2 [187724/1] question for 'world-gen.g.aaplimg.com|A' from 2001:8e0:40:2:dead:beef:0:208
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 [187724] world-gen.g.aaplimg.com: Wants DNSSEC processing in query for A
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 [187724] world-gen.g.aaplimg.com: Looking for CNAME cache hit of 'world-gen.g.aaplimg.com|CNAME'
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 [187724] world-gen.g.aaplimg.com: No CNAME cache hit of 'world-gen.g.aaplimg.com|CNAME' found
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 [187724] world-gen.g.aaplimg.com: Entire name 'world-gen.g.aaplimg.com', is negatively cached via 'g.aaplimg.com' for
another 44 seconds
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 [187724] g.aaplimg.com: Found cache hit for SOA: aad-dist.apple.com. hostmaster.apple.com. 1509039331 1800 300 60480
60[ttl=44]
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 Starting validation of answer to world-gen.g.aaplimg.com|A for [2001:8e0:40:2:dead:beef:0:208]:37674
Oct 31 15:15:41 ac-rns1 pdns_recursor[20365]: Oct 31 15:15:41 Answer to world-gen.g.aaplimg.com|A for [2001:8e0:40:2:dead:beef:0:208]:37674 validates as Insecure

We do see no evidence in the log why the record has been put into the negative cache!

We run recursor version 4.0.6 on Debian 8

Any idea, we are clueless ...

Regards

  Matthias

-- 
Matthias Cramer / mc322-ripe   Senior Network & Security Engineer
iway AG                        Phone +41 43 500 1111 <sip:0435001111>
Badenerstrasse 569             Fax   +41 44 271 3535 <sip:0442713535>
CH-8048 Zürich                 http://www.iway.ch/
GnuPG 1024D/2D208250 = DBC6 65B6 7083 1029 781E  3959 B62F DF1C 2D20 8250