NSEC3 caching doesn't seem to work
I was trying the aggressive NSEC3 caching in the v2.4.0 tag (4141975d).
$ cat config # Empty configuration
$ rm *.mdb
$ kresd -a 127.0.0.1#5354 -k root.keys -v
[tls] session ticket: epoch 374032, scheduling rotation check in 3276245 ms
[ ta ] new state of trust anchors for a domain: . 172800 DS 20326 8 2 E06D44B80B8F1D39A95C0B0D7C65D08458E880409BBC683457104237C7F8EC8D
[ ta ] new state of trust anchors for a domain: . 172800 DS 19036 8 2 49AAC11D7B6F6446702E54A1607371607A1A41855200FD2CE1CDDE32F24E8FB5
. 172800 DS 20326 8 2 E06D44B80B8F1D39A95C0B0D7C65D08458E880409BBC683457104237C7F8EC8D
[system] interactive mode
>
When I query for a name that exists, caching seems to work:
$ kdig @127.0.0.1 -p 5354 nic.cz | grep From
;; From 127.0.0.1@5354(UDP) in 870.8 ms
$ kdig @127.0.0.1 -p 5354 nic.cz | grep From
;; From 127.0.0.1@5354(UDP) in 0.2 ms
When I query for a name that doesn't exist, caching doesn't seem to work:
$ kdig @127.0.0.1 -p 5354 bla2.nic.cz | grep From
;; From 127.0.0.1@5354(UDP) in 1208.7 ms
$ kdig @127.0.0.1 -p 5354 bla2.nic.cz | grep From
;; From 127.0.0.1@5354(UDP) in 412.8 ms
Here's the server log:
[ 0][plan] plan 'bla2.nic.cz.' type 'A'
[63031][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[63031][cach] => no NSEC* cached for zone: cz.
[63031][zcut] found cut: cz. (rank 002 return codes: DS 0, DNSKEY 0)
[29651][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[29651][resl] => querying: '194.0.13.1' score: 95 zone cut: 'cz.' qname: 'NiC.cZ.' qtype: 'NS' proto: 'udp'
[29651][resl] => querying: '2001:678:10::1' score: 95 zone cut: 'cz.' qname: 'NiC.cZ.' qtype: 'NS' proto: 'udp'
[29651][iter] <= rcode: NOERROR
[29651][iter] <= continuing with qname minimization
[29651][resl] <= server: '194.0.13.1' rtt: 175 ms
[28702][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[28702][plan] plan 'nic.cz.' type 'DS'
[40723][iter] 'nic.cz.' type 'DS' id was assigned, parent id 28702
[40723][cach] => satisfied by exact RRset: rank 060, new TTL 3513
[40723][iter] <= rcode: NOERROR
[40723][vldr] <= DS: OK
[40723][vldr] <= parent: updating DS
[40723][vldr] <= answer valid, OK
[60915][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[60915][plan] plan 'nic.cz.' type 'DNSKEY'
[ 5674][iter] 'nic.cz.' type 'DNSKEY' id was assigned, parent id 60915
[ 5674][cach] => satisfied by exact RRset: rank 060, new TTL 1713
[ 5674][iter] <= rcode: NOERROR
[ 5674][vldr] <= parent: updating DNSKEY
[ 5674][vldr] <= answer valid, OK
[29278][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[29278][resl] => query[29278][resl] => querying: '2001:678:f::1' score: 11 zone cut: 'nic.cz.' qname: 'BLa2.Nic.Cz.' qtype: 'A' proto: 'udp'
[29278][iter] <= rcode: NXDOMAIN
[29278][vldr] <= answer valid, OK
[29278][cach] => stashed 61irsbhhtmb5arro3jt924s607pojbnu.nic.cz. NSEC3, rank 060, 149 B total, incl. 1 RRSIGs
[29278][cach] => stashed 7cnkran8antk3fkqoiivftbr83c4fk16.nic.cz. NSEC3, rank 060, 141 B total, incl. 1 RRSIGs
[29278][cach] => stashed 038c9fesqq3ofr3cefq91hji5h3mq5mc.nic.cz. NSEC3, rank 060, 150 B total, incl. 1 RRSIGs
[29278][cach] => stashed nic.cz. SOA, rank 060, 159 B total, incl. 1 RRSIGs
[29278][cach] => nsec_p stash skipped (extra TTL: 88)
[29278][resl] <= server: '194.0.12.1' rtt: 169 ms
[ 0][resl] AD: request classified as SECURE
[29278][resl] finished: 4, queries: 3, mempool: 82000 B
[ 0][plan] plan 'bla2.nic.cz.' type 'A'
[24186][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[24186][cach] => no NSEC* cached for zone: cz.
[24186][zcut] found cut: cz. (rank 002 return codes: DS 0, DNSKEY 0)
[ 390][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[ 390][resl] => querying: '194.0.12.1' score: 90 zone cut: 'cz.' qname: 'NIc.cZ.' qtype: 'NS' proto: 'udp'
[ 390][resl] => querying: '2001:678:f::1' score: 90 zone cut: 'cz.' qname: 'NIc.cZ.' qtype: 'NS' proto: 'udp'
[ 390][iter] <= rcode: NOERROR
[ 390][iter] <= continuing with qname minimization
[ 390][resl] <= server: '194.0.12.1' rtt: 180 ms
[21470][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[21470][plan] plan 'nic.cz.' type 'DS'
[60687][iter] 'nic.cz.' type 'DS' id was assigned, parent id 21470
[60687][cach] => satisfied by exact RRset: rank 060, new TTL 3512
[60687][iter] <= rcode: NOERROR
[60687][vldr] <= DS: OK
[60687][vldr] <= parent: updating DS
[60687][vldr] <= answer valid, OK
[31813][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[31813][plan] plan 'nic.cz.' type 'DNSKEY'
[52521][iter] 'nic.cz.' type 'DNSKEY' id was assigned, parent id 31813
[52521][cach] => satisfied by exact RRset: rank 060, new TTL 1712
[52521][iter] <= rcode: NOERROR
[52521][vldr] <= parent: updating DNSKEY
[52521][vldr] <= answer valid, OK
[47111][iter] 'bla2.nic.cz.' type 'A' id was assigned, parent id 0
[47111][resl] => query[47111][resl] => querying: '194.0.14.1' score: 116 zone cut: 'nic.cz.' qname: 'bla2.Nic.cZ.' qtype: 'A' proto: 'udp'
[47111][iter] <= rcode: NXDOMAIN
[47111][vldr] <= answer valid, OK
[47111][cach] => stashed 61irsbhhtmb5arro3jt924s607pojbnu.nic.cz. NSEC3, rank 060, 149 B total, incl. 1 RRSIGs
[47111][cach] => stashed 7cnkran8antk3fkqoiivftbr83c4fk16.nic.cz. NSEC3, rank 060, 141 B total, incl. 1 RRSIGs
[47111][cach] => stashed 038c9fesqq3ofr3cefq91hji5h3mq5mc.nic.cz. NSEC3, rank 060, 150 B total, incl. 1 RRSIGs
[47111][cach] => stashed nic.cz. SOA, rank 060, 159 B total, incl. 1 RRSIGs
[47111][cach] => nsec_p stash skipped (extra TTL: 89)
[47111][resl] <= server: '2001:678:11::1' rtt: 157 ms
[ 0][resl] AD: request classified as SECURE
[47111][resl] finished: 4, queries: 3, mempool: 82000 B
When I clear cache and restart the daemon, the caching sometimes works, but most of the time it doesn't. That's strange. I was trying to test aggressive NSEC3 caching originally with bla3, bla4, bla5, ... bla10.nic.cz, but it doesn't seem to work even when I ask the same name repetitively, so I'm not sure what am I doing wrong.