SERVFAIL on added KSK (DNSSEC) without reload of unbound

Wouter Wijngaards wouter at nlnetlabs.nl
Wed Aug 21 10:37:24 UTC 2019


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



More information about the Unbound-users mailing list