s0[1234]..se.prima-vod-prep-sec.service.cdn.cra.cz. fails to resolve with already cached subqueries
This is definitely broken upstream implementation, but we should be able to work around that. @nijel, I would also suggest submitting this to CRA, if you have any relationship to them. The clear cache behaviour:
[ 0][plan] plan 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A'
[54465][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[54465][plan] plan 'm.root-servers.net.' type 'AAAA'
[37257][iter] 'm.root-servers.net.' type 'AAAA' id was assigned, parent id 54465
[37257][resl] >< TA: '.'
[37257][resl] => querying: '2001:dc3::35' score: 40 zone cut: '.' m12n: 'NEt.' type: 'NS' proto: 'udp'
[37257][iter] <= using glue for 'f.gtld-servers.net.': '192.35.51.30'
[37257][iter] <= using glue for 'g.gtld-servers.net.': '192.42.93.30'
[37257][iter] <= using glue for 'b.gtld-servers.net.': '192.33.14.30'
[37257][iter] <= using glue for 'b.gtld-servers.net.': '2001:503:231d::2:30'
[37257][iter] <= using glue for 'l.gtld-servers.net.': '192.41.162.30'
[37257][iter] <= using glue for 'k.gtld-servers.net.': '192.52.178.30'
[37257][iter] <= using glue for 'i.gtld-servers.net.': '192.43.172.30'
[37257][iter] <= using glue for 'd.gtld-servers.net.': '192.31.80.30'
[37257][iter] <= using glue for 'c.gtld-servers.net.': '192.26.92.30'
[37257][iter] <= using glue for 'j.gtld-servers.net.': '192.48.79.30'
[37257][iter] <= using glue for 'a.gtld-servers.net.': '192.5.6.30'
[37257][iter] <= using glue for 'a.gtld-servers.net.': '2001:503:a83e::2:30'
[37257][iter] <= using glue for 'h.gtld-servers.net.': '192.54.112.30'
[37257][iter] <= using glue for 'm.gtld-servers.net.': '192.55.83.30'
[37257][iter] <= using glue for 'e.gtld-servers.net.': '192.12.94.30'
[37257][iter] <= referral response, follow
[37257][vldr] <= DS: OK
[37257][vldr] <= answer valid, OK
[37257][resl] <= server: '2001:dc3::35' rtt: 32 ms
[35585][iter] 'm.root-servers.net.' type 'AAAA' id was assigned, parent id 54465
[35585][plan] plan 'net.' type 'DNSKEY'
[ 1566][iter] 'net.' type 'DNSKEY' id was assigned, parent id 35585
[ 1566][resl] => querying: '192.55.83.30' score: 10 zone cut: 'net.' m12n: 'nET.' type: 'DNSKEY' proto: 'udp'
[ 1566][iter] <= rcode: NOERROR
[ 1566][vldr] <= parent: updating DNSKEY
[ 1566][vldr] <= answer valid, OK
[ 1566][resl] <= server: '192.55.83.30' rtt: 58 ms
[61036][iter] 'm.root-servers.net.' type 'AAAA' id was assigned, parent id 54465
[61036][resl] => querying: '192.41.162.30' score: 10 zone cut: 'net.' m12n: 'rOOT-seRVERS.net.' type: 'NS' proto: 'udp'
[61036][iter] <= using glue for 'a.root-servers.net.': '198.41.0.4'
[61036][iter] <= using glue for 'a.root-servers.net.': '2001:503:ba3e::2:30'
[61036][iter] <= using glue for 'h.root-servers.net.': '198.97.190.53'
[61036][iter] <= using glue for 'h.root-servers.net.': '2001:500:1::53'
[61036][iter] <= using glue for 'c.root-servers.net.': '192.33.4.12'
[61036][iter] <= using glue for 'c.root-servers.net.': '2001:500:2::c'
[61036][iter] <= using glue for 'g.root-servers.net.': '192.112.36.4'
[61036][iter] <= using glue for 'f.root-servers.net.': '192.5.5.241'
[61036][iter] <= using glue for 'f.root-servers.net.': '2001:500:2f::f'
[61036][iter] <= using glue for 'b.root-servers.net.': '192.228.79.201'
[61036][iter] <= using glue for 'b.root-servers.net.': '2001:500:84::b'
[61036][iter] <= using glue for 'j.root-servers.net.': '192.58.128.30'
[61036][iter] <= using glue for 'j.root-servers.net.': '2001:503:c27::2:30'
[61036][iter] <= using glue for 'k.root-servers.net.': '193.0.14.129'
[61036][iter] <= using glue for 'k.root-servers.net.': '2001:7fd::1'
[61036][iter] <= using glue for 'l.root-servers.net.': '199.7.83.42'
[61036][iter] <= using glue for 'l.root-servers.net.': '2001:500:9f::42'
[61036][iter] <= using glue for 'm.root-servers.net.': '2001:dc3::35'
[61036][iter] <= using glue for 'm.root-servers.net.': '202.12.27.33'
[61036][iter] <= using glue for 'i.root-servers.net.': '192.36.148.17'
[61036][iter] <= using glue for 'i.root-servers.net.': '2001:7fe::53'
[61036][iter] <= using glue for 'e.root-servers.net.': '192.203.230.10'
[61036][iter] <= using glue for 'd.root-servers.net.': '199.7.91.13'
[61036][iter] <= using glue for 'd.root-servers.net.': '2001:500:2d::d'
[61036][iter] <= referral response, follow
[61036][vldr] <= DS doesn't exist, going insecure
[61036][vldr] <= parent: updating DS
[61036][vldr] <= answer valid, OK
[61036][resl] <= server: '192.41.162.30' rtt: 119 ms
[34940][iter] 'm.root-servers.net.' type 'AAAA' id was assigned, parent id 54465
[34940][resl] => querying: '2001:500:9f::42' score: 10 zone cut: 'root-servers.net.' m12n: 'm.rOoT-SERVERS.neT.' type: 'AAAA' proto: 'udp'
[34940][iter] <= using glue for 'a.root-servers.net.': '198.41.0.4'
[34940][iter] <= using glue for 'a.root-servers.net.': '2001:503:ba3e::2:30'
[34940][iter] <= using glue for 'b.root-servers.net.': '192.228.79.201'
[34940][iter] <= using glue for 'b.root-servers.net.': '2001:500:84::b'
[34940][iter] <= using glue for 'c.root-servers.net.': '192.33.4.12'
[34940][iter] <= using glue for 'c.root-servers.net.': '2001:500:2::c'
[34940][iter] <= using glue for 'd.root-servers.net.': '199.7.91.13'
[34940][iter] <= using glue for 'd.root-servers.net.': '2001:500:2d::d'
[34940][iter] <= using glue for 'e.root-servers.net.': '192.203.230.10'
[34940][iter] <= using glue for 'e.root-servers.net.': '2001:500:a8::e'
[34940][iter] <= using glue for 'f.root-servers.net.': '192.5.5.241'
[34940][iter] <= using glue for 'f.root-servers.net.': '2001:500:2f::f'
[34940][iter] <= using glue for 'g.root-servers.net.': '192.112.36.4'
[34940][iter] <= using glue for 'g.root-servers.net.': '2001:500:12::d0d'
[34940][iter] <= using glue for 'h.root-servers.net.': '198.97.190.53'
[34940][iter] <= using glue for 'h.root-servers.net.': '2001:500:1::53'
[34940][iter] <= using glue for 'i.root-servers.net.': '192.36.148.17'
[34940][iter] <= using glue for 'i.root-servers.net.': '2001:7fe::53'
[34940][iter] <= using glue for 'j.root-servers.net.': '192.58.128.30'
[34940][iter] <= using glue for 'j.root-servers.net.': '2001:503:c27::2:30'
[34940][iter] <= using glue for 'k.root-servers.net.': '193.0.14.129'
[34940][iter] <= using glue for 'k.root-servers.net.': '2001:7fd::1'
[34940][iter] <= using glue for 'l.root-servers.net.': '199.7.83.42'
[34940][iter] <= using glue for 'l.root-servers.net.': '2001:500:9f::42'
[34940][iter] <= using glue for 'm.root-servers.net.': '2001:dc3::35'
[34940][iter] <= using glue for 'm.root-servers.net.': '202.12.27.33'
[34940][iter] <= rcode: NOERROR
[34940][resl] <= server: '2001:500:9f::42' rtt: 12 ms
[46566][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[46566][resl] => querying: '2001:dc3::35' score: 36 zone cut: '.' m12n: 'cz.' type: 'NS' proto: 'udp'
[46566][iter] <= using glue for 'c.ns.nic.cz.': '194.0.14.1'
[46566][iter] <= using glue for 'c.ns.nic.cz.': '2001:678:11::1'
[46566][iter] <= using glue for 'b.ns.nic.cz.': '194.0.13.1'
[46566][iter] <= using glue for 'b.ns.nic.cz.': '2001:678:10::1'
[46566][iter] <= using glue for 'a.ns.nic.cz.': '194.0.12.1'
[46566][iter] <= using glue for 'a.ns.nic.cz.': '2001:678:f::1'
[46566][iter] <= using glue for 'd.ns.nic.cz.': '193.29.206.1'
[46566][iter] <= using glue for 'd.ns.nic.cz.': '2001:678:1::1'
[46566][iter] <= referral response, follow
[46566][vldr] <= DS: OK
[46566][vldr] <= answer valid, OK
[46566][resl] <= server: '2001:dc3::35' rtt: 31 ms
[63190][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[63190][plan] plan 'cz.' type 'DNSKEY'
[17095][iter] 'cz.' type 'DNSKEY' id was assigned, parent id 63190
[17095][resl] => querying: '2001:678:1::1' score: 10 zone cut: 'cz.' m12n: 'cZ.' type: 'DNSKEY' proto: 'udp'
[17095][iter] <= rcode: NOERROR
[17095][vldr] <= parent: updating DNSKEY
[17095][vldr] <= answer valid, OK
[17095][resl] <= server: '2001:678:1::1' rtt: 22 ms
[62591][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[62591][resl] => querying: '2001:678:11::1' score: 10 zone cut: 'cz.' m12n: 'Cra.Cz.' type: 'NS' proto: 'udp'
[62591][resl] => querying: '194.0.14.1' score: 10 zone cut: 'cz.' m12n: 'Cra.Cz.' type: 'NS' proto: 'udp'
[62591][iter] <= using glue for 'ns.bluetone.cz.': '212.158.128.12'
[62591][iter] <= using glue for 'ns.bluetone.cz.': '2a02:a40:2::12'
[62591][iter] <= using glue for 'ns1.bluetone.cz.': '212.158.128.13'
[62591][iter] <= using glue for 'ns1.bluetone.cz.': '2a02:a40:2::13'
[62591][iter] <= using glue for 'ns2.bluetone.cz.': '85.207.207.75'
[62591][iter] <= using glue for 'ns2.bluetone.cz.': '2a02:a40:2:200::2:200'
[62591][iter] <= referral response, follow
[62591][vldr] <= DS doesn't exist, going insecure
[62591][vldr] <= answer valid, OK
[62591][resl] <= server: '2001:678:11::1' rtt: 271 ms
[62591][resl] <= server: '194.0.14.1' rtt: >=21 ms
[47400][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[47400][resl] => querying: '2a02:a40:2:200::2:200' score: 10 zone cut: 'cra.cz.' m12n: 'CDN.CrA.CZ.' type: 'NS' proto: 'udp'
[47400][iter] <= rcode: NOERROR
[47400][iter] <= found cut, retrying with non-minimized name
[47400][resl] <= server: '2a02:a40:2:200::2:200' rtt: 13 ms
[42137][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[42137][resl] => querying: '2a02:a40:2::13' score: 10 zone cut: 'cra.cz.' m12n: 'sE04.SE.PrImA-vod-PrEp-Sec.SERvicE.CdN.cRa.cZ.' type: 'A' proto: 'udp'
[42137][iter] <= using glue for 'sr02.cdn.cra.cz.': '84.244.72.20'
[42137][iter] <= using glue for 'sr01.cdn.cra.cz.': '82.99.164.132'
[42137][iter] <= referral response, follow
[42137][resl] <= server: '2a02:a40:2::13' rtt: 12 ms
[40236][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[40236][resl] => querying: '84.244.72.20' score: 10 zone cut: 'service.cdn.cra.cz.' m12n: 'SE04.Se.PRiMA-VoD-PreP-sec.ServICE.cDN.cRA.CZ.' type: 'A' proto: 'udp'
[40236][iter] <= rcode: NOERROR
[40236][resl] <= server: '84.244.72.20' rtt: 14 ms
[ 0][resl] finished: 4, queries: 4, mempool: 65600 Band returns:
;; ->>HEADER<<- opcode: QUERY; status: NOERROR; id: 9055
;; Flags: qr rd ra; QUERY: 1; ANSWER: 1; AUTHORITY: 0; ADDITIONAL: 1
;; EDNS PSEUDOSECTION:
;; Version: 0; flags: do; UDP size: 4096 B; ext-rcode: Unused
;; QUESTION SECTION:
;; se04.se.prima-vod-prep-sec.service.cdn.cra.cz. IN A
;; ANSWER SECTION:
se04.se.prima-vod-prep-sec.service.cdn.cra.cz. 60 IN A 84.244.95.23
;; Received 90 B
;; Time 2017-01-21 07:37:45 CET
;; From ::1@51596(UDP) in 588.8 msOn a second attempt it fails:
[ 0][plan] plan 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A'
[30178][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[30178][resl] => NS is provably without DS, going insecure
[29832][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[29832][plan] plan 'sr02.cdn.cra.cz.' type 'AAAA'
[56699][iter] 'sr02.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 29832
[41635][iter] 'sr02.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 29832
[41635][plan] plan 'ns2.bluetone.cz.' type 'AAAA'
[17422][iter] 'ns2.bluetone.cz.' type 'AAAA' id was assigned, parent id 41635
[20659][iter] 'ns2.bluetone.cz.' type 'AAAA' id was assigned, parent id 41635
[20659][resl] => querying: '2001:678:10::1' score: 10 zone cut: 'cz.' m12n: 'BlueTONE.Cz.' type: 'NS' proto: 'udp'
[20659][iter] <= using glue for 'ns.bluetone.cz.': '212.158.128.12'
[20659][iter] <= using glue for 'ns.bluetone.cz.': '2a02:a40:2::12'
[20659][iter] <= using glue for 'ns1.bluetone.cz.': '212.158.128.13'
[20659][iter] <= using glue for 'ns1.bluetone.cz.': '2a02:a40:2::13'
[20659][iter] <= using glue for 'ns2.bluetone.cz.': '85.207.207.75'
[20659][iter] <= using glue for 'ns2.bluetone.cz.': '2a02:a40:2:200::2:200'
[20659][iter] <= referral response, follow
[20659][resl] <= server: '2001:678:10::1' rtt: 22 ms
[11105][iter] 'ns2.bluetone.cz.' type 'AAAA' id was assigned, parent id 41635
[11105][resl] => querying: '2a02:a40:2::12' score: 10 zone cut: 'bluetone.cz.' m12n: 'ns2.blUeTOnE.cZ.' type: 'AAAA' proto: 'udp'
[11105][iter] <= using glue for 'ns.bluetone.cz.': '212.158.128.12'
[11105][iter] <= using glue for 'ns.bluetone.cz.': '2a02:a40:2::12'
[11105][iter] <= using glue for 'ns1.bluetone.cz.': '212.158.128.13'
[11105][iter] <= using glue for 'ns1.bluetone.cz.': '2a02:a40:2::13'
[11105][iter] <= using glue for 'ns2.bluetone.cz.': '2a02:a40:2:200::2:200'
[11105][iter] <= using glue for 'ns2.bluetone.cz.': '85.207.207.75'
[11105][iter] <= rcode: NOERROR
[11105][resl] <= server: '2a02:a40:2::12' rtt: 11 ms
[23289][iter] 'sr02.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 29832
[23289][resl] => querying: '2a02:a40:2:200::2:200' score: 13 zone cut: 'cra.cz.' m12n: 'Cdn.Cra.Cz.' type: 'NS' proto: 'udp'
[23289][iter] <= rcode: NOERROR
[23289][iter] <= found cut, retrying with non-minimized name
[23289][resl] <= server: '2a02:a40:2:200::2:200' rtt: 13 ms
[55206][iter] 'sr02.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 29832
[55206][resl] => querying: '2a02:a40:2:200::2:200' score: 13 zone cut: 'cra.cz.' m12n: 'SR02.cDN.cRa.cz.' type: 'AAAA' proto: 'udp'
[55206][iter] <= rcode: NOERROR
[55206][ pc ] => answer cached for TTL=900
[55206][resl] <= server: '2a02:a40:2:200::2:200' rtt: 13 ms
[ 1608][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[ 1608][plan] plan 'sr02.cdn.cra.cz.' type 'A'
[11065][iter] 'sr02.cdn.cra.cz.' type 'A' id was assigned, parent id 1608
[22035][iter] 'sr02.cdn.cra.cz.' type 'A' id was assigned, parent id 1608
[22035][resl] => querying: '2a02:a40:2::12' score: 11 zone cut: 'cra.cz.' m12n: 'CDn.CRa.CZ.' type: 'NS' proto: 'udp'
[22035][iter] <= rcode: NOERROR
[22035][iter] <= found cut, retrying with non-minimized name
[22035][resl] <= server: '2a02:a40:2::12' rtt: 11 ms
[12861][iter] 'sr02.cdn.cra.cz.' type 'A' id was assigned, parent id 1608
[12861][resl] => querying: '2a02:a40:2::13' score: 12 zone cut: 'cra.cz.' m12n: 'sR02.cdn.cRA.Cz.' type: 'A' proto: 'udp'
[12861][iter] <= referral response, follow
[12861][resl] <= server: '2a02:a40:2::13' rtt: 12 ms
[48703][iter] 'sr02.cdn.cra.cz.' type 'A' id was assigned, parent id 1608
[48703][plan] plan 'ns2.bluetone.cz.' type 'AAAA'
[32274][iter] 'ns2.bluetone.cz.' type 'AAAA' id was assigned, parent id 48703
[32274][ rc ] => satisfied from cache
[32274][iter] <= rcode: NOERROR
[32274][vldr] <= cached insecure response, going insecure
[ 4634][iter] 'sr02.cdn.cra.cz.' type 'A' id was assigned, parent id 1608
[ 4634][ rc ] => satisfied from cache
[ 4634][iter] <= rcode: NOERROR
[ 4634][vldr] <= cached insecure response, going insecure
[30962][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[30962][resl] => querying: '84.244.72.20' score: 14 zone cut: 'service.cdn.cra.cz.' m12n: 'PRIMa-VOD-prep-SEC.ServICe.cdn.cRA.Cz.' type: 'NS' proto: 'udp'
[30962][iter] <= malformed response
[14962][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[14962][resl] => querying: '84.244.72.20' score: 14 zone cut: 'service.cdn.cra.cz.' m12n: 'prima-vod-prep-sec.service.cdn.cra.cz.' type: 'NS' proto: 'udp'
[14962][iter] <= rcode: NOTIMPL
[14962][resl] => server: '84.244.72.20' flagged as 'bad'
[30025][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[30025][plan] plan 'sr01.cdn.cra.cz.' type 'AAAA'
[58302][iter] 'sr01.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 30025
[42496][iter] 'sr01.cdn.cra.cz.' type 'AAAA' id was assigned, parent id 30025
[42496][resl] => querying: '2a02:a40:2::13' score: 12 zone cut: 'cdn.cra.cz.' m12n: 'Sr01.Cdn.cra.Cz.' type: 'AAAA' proto: 'udp'
[42496][iter] <= rcode: NOERROR
[42496][ pc ] => answer cached for TTL=900
[42496][resl] <= server: '2a02:a40:2::13' rtt: 11 ms
[22193][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[22193][plan] plan 'sr01.cdn.cra.cz.' type 'A'
[ 4642][iter] 'sr01.cdn.cra.cz.' type 'A' id was assigned, parent id 22193
[28261][iter] 'sr01.cdn.cra.cz.' type 'A' id was assigned, parent id 22193
[28261][resl] => querying: '2a02:a40:2::13' score: 11 zone cut: 'cdn.cra.cz.' m12n: 'sr01.CDN.CRa.cZ.' type: 'A' proto: 'udp'
[28261][iter] <= rcode: NOERROR
[28261][resl] <= server: '2a02:a40:2::13' rtt: 11 ms
[61912][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[61912][resl] => querying: '82.99.164.132' score: 10 zone cut: 'service.cdn.cra.cz.' m12n: 'prima-vod-prep-sec.service.cdn.cra.cz.' type: 'NS' proto: 'udp'
[61912][iter] <= rcode: NOTIMPL
[61912][resl] => server: '82.99.164.132' flagged as 'bad'
[ 3184][iter] 'se04.se.prima-vod-prep-sec.service.cdn.cra.cz.' type 'A' id was assigned, parent id 0
[ 3184][resl] => unresolvable NS address, bailing out
[ 3184][resl] => no valid NS left
[ 0][resl] finished: 8, queries: 7, mempool: 65600 Band returns:
;; ->>HEADER<<- opcode: QUERY; status: SERVFAIL; id: 14060
;; Flags: qr rd ra; QUERY: 1; ANSWER: 0; AUTHORITY: 0; ADDITIONAL: 1
;; EDNS PSEUDOSECTION:
;; Version: 0; flags: do; UDP size: 4096 B; ext-rcode: Unused
;; QUESTION SECTION:
;; se04.se.prima-vod-prep-sec.service.cdn.cra.cz. IN A
;; Received 74 B
;; Time 2017-01-21 07:40:44 CET
;; From ::1@51596(UDP) in 149.8 msPerhaps treating NOTIMPL same as NXDOMAIN in qname minimization path would fix that?