SERVFAIL on added KSK (DNSSEC) without reload of unbound

Wed Aug 21 10:18:11 UTC 2019

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