Hi Peter, Yes the resolver is supposed to cache the KSK and ZSKs with the TTL that they have. This is the supposed functionality of DNSSEC, eg. resolvers cache the date for their TTL and it remains valid for that time.
If you enter new keys and use them without waiting for the TTL(s) to expire, it won't work. There are several drafts, RFCs and documents on the matter. Called rollover timeout schedules, and similar, usually also try to factor in the time it takes for the data to propagate through the publication system, secondaries and so on. If you add a new key and try to use it without waiting for the DNSKEY rrset TTL to expire, it won't be there in all caches, and the test you set up simulates this. Also, before you can remove a key, you have to wait for all the signatures with it to be gone and their TTL to expire, and for KSKs for the DS record to be gone and its TTL to expire. There are tables for action sequences and formulas to calculate the timers, in advice documents. You can get unbound to print a summary of the validation failure with val-log-level: 2 , in this case, I think, just that it cannot find the right key, because it was not there when the key lookup happened. Best regards, Wouter On 21/08/2019 12:18, Peter Larsen via Unbound-users wrote: > I have seen this for a while > > My conclusion is that unbound caches the KSK/ZSK’s with the first result, > then on the second queries (after the zone is added with more KSK/ZSK’s) it > uses the cache to search for the keyset, and does not find it. > > it would eventually resolve itself if unbound is reloaded (killed) or the > first (initiel) query expire’s in TTL.. (not 100% sure on the second claim, > but it will reset and start to work eventually) > > > is this something anyone else have seen? > > > > unbound tested here is 1.9.2, but i have seen it in quite a few versions > > asking for soa for the zone: > > $ dig -p 5353 @ xxxxxxxxx domain11.dk +dnssec soa > > ; <<>> DiG 9.10.6 <<>> -p 5353 @ xxxxxxxxx domain11.dk +dnssec soa > ; (1 server found) > ;; global options: +cmd > ;; Got answer: > ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 18271 > ;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1 > > ;; OPT PSEUDOSECTION: > ; EDNS: version: 0, flags: do; udp: 4096 > ;; QUESTION SECTION: > ;domain11.dk. IN SOA > > ;; ANSWER SECTION: > domain11.dk. 42513 IN SOA ns1.gratisdns.dk. > hostmaster.gratisdns.dk. 2019082008 14400 3600 2419000 43200 > domain11.dk. 42513 IN RRSIG SOA 8 2 43200 20190919111321 > 20190820111321 39459 domain11.dk. > BVw1mc/q4arnQAYOiAno50dHs1EP4xm9MCotfg5JTgzbtaobb60GKa/U > rUCHT4n4U2DvjyZl+5QfIM6G2pImYiN33wYXMilLcAsfzStMxqL8ISGq > HWoh8DLDSh0ZJSF3KDfnJEeOe6mOtLqSEwwX/yx9RcLkxC4S5SsLcdCS > XfpN/64z4KqmDmQeh08bntLZmm1h4nz1V9cTquyPT+pQ5fJm0fg0k1c4 > FB0yI9c+ObkK+LDrhUPLmPxsi9MT0BZtu2ruIxmYrsdegfJoOEU5RQbr > oL1WbbeJqsrNYQTBGhDCSvmorRNwxi71FCJM3Lvd9pIUsHbdXo++7G5j ZwiFng== > > ;; Query time: 1 msec > ;; SERVER: xxxxxxxxx#5353(xxxxxxxxx) > ;; WHEN: Tue Aug 20 15:11:54 CEST 2019 > ;; MSG SIZE rcvd: 400 > > > I add a KSK/ZSK, reload it, soa updates on all auth nameservers, checks cache > dns (I do not add the KSK to the registry, it’s not needed for the error): > > asking for either a TXT or a SOA of a subdomain (nonecached answer): > > > $ dig -p 5353 @ xxxxxxxxx domain11.dk +dnssec txt > > ; <<>> DiG 9.10.6 <<>> -p 5353 @ xxxxxxxxx domain11.dk +dnssec txt > ; (1 server found) > ;; global options: +cmd > ;; Got answer: > ;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 59798 > ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1 > > ;; OPT PSEUDOSECTION: > ; EDNS: version: 0, flags: do; udp: 4096 > ;; QUESTION SECTION: > ;domain11.dk. IN TXT > > ;; Query time: 242 msec > ;; SERVER: xxxxxxxxx#5353(xxxxxxxxx) > ;; WHEN: Tue Aug 20 15:19:12 CEST 2019 > ;; MSG SIZE rcvd: 40 > > > > the original (pre KSK/ZSK add) still answers correctly > > $ dig -p 5353 @xxxxxxxxx domain11.dk +dnssec soa > > ; <<>> DiG 9.10.6 <<>> -p 5353 @xxxxxxxxx domain11.dk +dnssec soa > ; (1 server found) > ;; global options: +cmd > ;; Got answer: > ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 51775 > ;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1 > > ;; OPT PSEUDOSECTION: > ; EDNS: version: 0, flags: do; udp: 4096 > ;; QUESTION SECTION: > ;domain11.dk. IN SOA > > ;; ANSWER SECTION: > domain11.dk. 41305 IN SOA ns1.gratisdns.dk. > hostmaster.gratisdns.dk. 2019082008 14400 3600 2419000 43200 > domain11.dk. 41305 IN RRSIG SOA 8 2 43200 20190919111321 > 20190820111321 39459 domain11.dk. > BVw1mc/q4arnQAYOiAno50dHs1EP4xm9MCotfg5JTgzbtaobb60GKa/U > rUCHT4n4U2DvjyZl+5QfIM6G2pImYiN33wYXMilLcAsfzStMxqL8ISGq > HWoh8DLDSh0ZJSF3KDfnJEeOe6mOtLqSEwwX/yx9RcLkxC4S5SsLcdCS > XfpN/64z4KqmDmQeh08bntLZmm1h4nz1V9cTquyPT+pQ5fJm0fg0k1c4 > FB0yI9c+ObkK+LDrhUPLmPxsi9MT0BZtu2ruIxmYrsdegfJoOEU5RQbr > oL1WbbeJqsrNYQTBGhDCSvmorRNwxi71FCJM3Lvd9pIUsHbdXo++7G5j ZwiFng== > > ;; Query time: 1 msec > ;; SERVER: xxxxxxxxx#5353(xxxxxxxxx) > ;; WHEN: Tue Aug 20 15:32:01 CEST 2019 > ;; MSG SIZE rcvd: 400 > > > > if unbound is reloaded (killed and started again) it works… > > some debug info > > > before adding a extra KSK/ZSK > > > [1566303150] unbound[67502:0] debug: iter_handle processing q with state > QUERY RESPONSE STATE > [1566303150] unbound[67502:0] info: query response was nodata ANSWER > [1566303150] unbound[67502:0] debug: iter_handle processing q with state > FINISHED RESPONSE STATE > [1566303150] unbound[67502:0] info: finishing processing for domain11.dk. TXT > IN > [1566303150] unbound[67502:0] debug: mesh_run: iterator module exit state is > module_finished > [1566303150] unbound[67502:0] debug: validator[module 0] operate: > extstate:module_wait_module event:module_event_moddone > [1566303150] unbound[67502:0] info: validator operate: query domain11.dk. TXT > IN > [1566303150] unbound[67502:0] debug: validator: nextmodule returned > [1566303150] unbound[67502:0] debug: val handle processing q with state > VAL_INIT_STATE > [1566303150] unbound[67502:0] debug: validator classification nodata > [1566303150] unbound[67502:0] info: signer is domain11.dk. TYPE0 CLASS0 > [1566303150] unbound[67502:0] debug: val handle processing q with state > VAL_FINDKEY_STATE > [1566303150] unbound[67502:0] info: validator: FindKey domain11.dk. TXT IN > [1566303150] unbound[67502:0] debug: val handle processing q with state > VAL_VALIDATE_STATE > [1566303150] unbound[67502:0] info: verify rrset domain11.dk. SOA IN > [1566303150] unbound[67502:0] debug: verify sig 39600 8 > [1566303150] unbound[67502:0] debug: verify result: sec_status_secure > [1566303150] unbound[67502:0] info: verify rrset domain11.dk. NSEC IN > [1566303150] unbound[67502:0] debug: verify sig 39600 8 > [1566303150] unbound[67502:0] debug: verify result: sec_status_secure > [1566303150] unbound[67502:0] debug: Validating a nodata response > [1566303150] unbound[67502:0] debug: successfully validated NODATA response. > [1566303150] unbound[67502:0] info: validate(nodata): sec_status_secure > [1566303150] unbound[67502:0] debug: val handle processing q with state > VAL_FINISHED_STATE > [1566303150] unbound[67502:0] info: validation success domain11.dk. TXT IN > [1566303150] unbound[67502:0] info: negcache insert for zone domain11.dk. SOA > IN > [1566303150] unbound[67502:0] info: negcache rr domain11.dk. NSEC IN > [1566303150] unbound[67502:0] debug: mesh_run: validator module exit state is > module_finished > [1566303150] unbound[67502:0] debug: query took 0.015346 sec > > > after adding a extra KSK/ZSK: > > > [1566303221] unbound[67502:0] debug: iter_handle processing q with state > QUERY RESPONSE STATE > [1566303221] unbound[67502:0] info: query response was nodata ANSWER > [1566303221] unbound[67502:0] debug: iter_handle processing q with state > FINISHED RESPONSE STATE > [1566303221] unbound[67502:0] info: finishing processing for domain11.dk. > CNAME IN > [1566303221] unbound[67502:0] debug: mesh_run: iterator module exit state is > module_finished > [1566303221] unbound[67502:0] debug: validator[module 0] operate: > extstate:module_restart_next event:module_event_moddone > [1566303221] unbound[67502:0] info: validator operate: query domain11.dk. > CNAME IN > [1566303221] unbound[67502:0] info: validator operate: chased to . TYPE0 > CLASS0 > [1566303221] unbound[67502:0] debug: validator: nextmodule returned > [1566303221] unbound[67502:0] debug: val handle processing q with state > VAL_INIT_STATE > [1566303221] unbound[67502:0] debug: validator classification nodata > [1566303221] unbound[67502:0] info: signer is domain11.dk. TYPE0 CLASS0 > [1566303221] unbound[67502:0] debug: val handle processing q with state > VAL_FINDKEY_STATE > [1566303221] unbound[67502:0] info: validator: FindKey domain11.dk. CNAME IN > [1566303221] unbound[67502:0] debug: val handle processing q with state > VAL_VALIDATE_STATE > [1566303221] unbound[67502:0] info: verify rrset domain11.dk. SOA IN > [1566303221] unbound[67502:0] debug: verify sig 39459 8 > [1566303221] unbound[67502:0] debug: verify: could not find appropriate key > [1566303221] unbound[67502:0] debug: rrset failed to verify: no valid > signatures > [1566303221] unbound[67502:0] debug: verify result: sec_status_bogus > [1566303221] unbound[67502:0] info: validator: response has failed AUTHORITY > rrset: domain11.dk. SOA IN > [1566303221] unbound[67502:0] info: Validate: message contains bad rrsets > [1566303221] unbound[67502:0] debug: val handle processing q with state > VAL_FINISHED_STATE > [1566303221] unbound[67502:0] debug: mesh_run: validator module exit state is > module_finished > [1566303221] unbound[67502:0] debug: query took 0.266759 sec > > > > regards, Peter Larsen
