Hello all,
I am running Unbound 1.4.22 on Debian 7.9 for production and have also installed Unbound 1.5.6-1 on Debian 8.2. Both are validating with nearly identical config.
The issue is that I am receiving different results for following query (I am sorry for long post):
1.4.22:
dig -t a www.mikulasske.cz -p1053 @127.0.0.1
; <<>> DiG 9.8.4-rpz2+rl005.12-P1 <<>> -t a www.mikulasske.cz -p1053 @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 48991
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;www.mikulasske.cz. IN A
;; Query time: 31 msec
;; SERVER: 127.0.0.1#1053(127.0.0.1)
;; WHEN: Wed Nov 25 15:49:51 2015
;; MSG SIZE rcvd: 35
1.5.6:
dig -t a www.mikulasske.cz @127.0.0.1
; <<>> DiG 9.9.5-9+deb8u3-Debian <<>> -t a www.mikulasske.cz @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 59981
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;www.mikulasske.cz. IN A
;; ANSWER SECTION:
www.mikulasske.cz. 86400 IN A 195.113.226.123
;; Query time: 54 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Wed Nov 25 15:51:10 CET 2015
;; MSG SIZE rcvd: 62
According to the dnsviz.net the domain seems to be DNSSEC broken.
Both versions were freshly restarted and this was the 1st query to them. I can paste the config if needed
Debug for 1.5.6 validating positively:
Nov 25 15:51:10 unbound[31660:2] info: iterator operate: query mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] debug: process_response: new external response event
Nov 25 15:51:10 unbound[31660:2] info: scrub for mikulasske.cz. NS IN
Nov 25 15:51:10 unbound[31660:2] info: response for mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] info: reply from <mikulasske.cz.> 195.113.226.123#53
Nov 25 15:51:10 unbound[31660:2] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
mikulasske.cz. IN DNSKEY
;; ANSWER SECTION:
mikulasske.cz. 86400 IN DNSKEY 257 3 8 AwEAAdBISW2rX+jvm8tYslCVYi5k5z/91+nI9V6pNsN/YHpFfryuErF2SqAFahAzr2gkdhKH+PUmmZmMc3ZqjcN37vD17awEydCZtr/se2Ruz+FuRKQNab93cTOt/TvJdmUCunFREhA9rIjunjYqlEAYqKWbsZ64qxUdU0NYNctl9bP59DbNjBELJaoSvrRs2DtJtJsZsCq5ASiVj6cI1Gu4Fox3SX5eKvReB7EjID7GNDVUpbd0ARQ3iVEFBl/V73+HtTCc/V7HxNggjhAQzUCrEOlhpM6pbNCaF8dpbqi4Y/zGIk47+icL0MNvd9YIrLFYFlgswDVfd/3uwReMXVHqYFU= ;{id = 42592 (ksk), size = 2048b}
mikulasske.cz. 86400 IN DNSKEY 256 3 8 AwEAAbqo8jx7NbXoqKgswl+EwFPkHAhjdS6+JkhmFo8tygV2pTD7RYpU+5MBLZxxWmx8DwfqbTTFx+Hb/qeQr8GvgWWTStNFfAsR2jWg4sdXgX5PozjrCS3H7VAlCqyhlUOwwaiLu79DGudHrqRwzGRT6/8jlfO5h74F4J7BfnaYMDzSBmSbUAL58I6jx9varHzulzq/eEblfxlFYxhGC+ubR95QLAkSMgqBTv/2jgt04e2daUmTDna1Rdn+cnfYf2Aj5O8ycrbPVQzdSqajfu/ohgsvCD7+xuDQ/7KE0O7BBX/2llZJI0BrRVjM36iwFAsXDTyL3Nnj/RQEGTZ3YH33nL0= ;{id = 35946 (zsk), size = 2048b}
mikulasske.cz. 86400 IN RRSIG DNSKEY 8 2 86400 20160118212400 20151123212400 35946 mikulasske.cz. cfbl4FW0b4+kZ8bWspj28Z9g0WTgr6m2lZQh4qYvK+ENGRm2p2GD7p9ie4ItsRvWoSOYckk+Nn+Z4gd7j5pwEueHrp85/i9b7ij1rT9I//gM3Q9T80TQuaNZVGilzQowN2DZMI4N7aDcoAkM2R4zeuSyhbxvepEAvK9p55QRr6PMq2l0xshMd6b/DK8biPEiP0Ym3+HrGCNNiNWnv2I3PYKJ2K/SIPjuQLIcY35kuXrTSxULYIj3hKbBrW/Wvr7YVYQHmd1CTwvLCidydCGqiEJcfNyIaJDiqdQqTxOqU/oIccaGRqfZ7VHxjCJD5TfLuIGWMQ7Uns5GLQ/ZZfFzWw== ;{id = 35946}
mikulasske.cz. 86400 IN RRSIG DNSKEY 8 2 86400 20160118212400 20151123212400 42592 mikulasske.cz. LacHyWu+udogAFayox3wNFpCdW18uvREEykZ7xpAtw0UWdCPJKqZPbXsn+mRhn9Rvg49JAy0DZUk7pwmCVrbtlck6Q63l2iR36xyxr/Kq20hKfCn23JX6lVdnFxyqz4Uqc1h0sPm61PeGnt335fFenj51Px6+ePKpizY3D9NtPBWuKao3A+klGvShqRknwTAdsyYa43C7ZA4cUZz2Sbm6ZtvN8IeNHL/jw1H0z9r5lW/xhBWSqjP7duXRflGDnL+WOzYd+CPIHSuDy9NiZo1V/OvpXHc8QFlXGYPq8+YWZBDwnt2Hal1bH50hxz1jUUfJVK+uwSrI3a9pDqWT7QE9g== ;{id = 42592}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 1185
Nov 25 15:51:10 unbound[31660:2] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 25 15:51:10 unbound[31660:2] info: query response was ANSWER
Nov 25 15:51:10 unbound[31660:2] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Nov 25 15:51:10 unbound[31660:2] info: finishing processing for mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] debug: mesh_run: iterator module exit state is module_finished
Nov 25 15:51:10 unbound[31660:2] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 25 15:51:10 unbound[31660:2] info: validator operate: query mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] debug: validator: nextmodule returned
Nov 25 15:51:10 unbound[31660:2] debug: not validating response, is valrec(validation recursion lookup)
Nov 25 15:51:10 unbound[31660:2] debug: mesh_run: validator module exit state is module_finished
Nov 25 15:51:10 unbound[31660:2] info: validator: inform_super, sub is mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] info: super is www.mikulasske.cz. A IN
Nov 25 15:51:10 unbound[31660:2] debug: attempt DS match algo 8 keytag 42592
Nov 25 15:51:10 unbound[31660:2] debug: DS match digest ok, trying signature
Nov 25 15:51:10 unbound[31660:2] debug: DS matched DNSKEY.
Nov 25 15:51:10 unbound[31660:2] info: validated DNSKEY mikulasske.cz. DNSKEY IN
Nov 25 15:51:10 unbound[31660:2] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Nov 25 15:51:10 unbound[31660:2] info: validator operate: query www.mikulasske.cz. A IN
Nov 25 15:51:10 unbound[31660:2] debug: val handle processing q with state VAL_FINDKEY_STATE
Nov 25 15:51:10 unbound[31660:2] info: validator: FindKey www.mikulasske.cz. A IN
Nov 25 15:51:10 unbound[31660:2] debug: val handle processing q with state VAL_VALIDATE_STATE
Nov 25 15:51:10 unbound[31660:2] info: verify rrset www.mikulasske.cz. A IN
Nov 25 15:51:10 unbound[31660:2] debug: verify sig 35946 8
Nov 25 15:51:10 unbound[31660:2] debug: verify result: sec_status_secure
Nov 25 15:51:10 unbound[31660:2] info: verify rrset _443._tcp.webmail.mikulasske.cz. NSEC IN
Nov 25 15:51:10 unbound[31660:2] debug: verify sig 35946 8
Nov 25 15:51:10 unbound[31660:2] debug: verify result: sec_status_secure
Nov 25 15:51:10 unbound[31660:2] debug: Validating a positive response
Nov 25 15:51:10 unbound[31660:2] debug: Successfully validated positive response
Nov 25 15:51:10 unbound[31660:2] info: validate(positive): sec_status_secure
Nov 25 15:51:10 unbound[31660:2] debug: val handle processing q with state VAL_FINISHED_STATE
Nov 25 15:51:10 unbound[31660:2] info: validation success www.mikulasske.cz. A IN
Debug for 1.4.22 where validation fails:
Nov 25 15:49:18 unbound[24458:1] info: iterator operate: query mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: process_response: new external response event
Nov 25 15:49:18 unbound[24458:1] info: scrub for mikulasske.cz. NS IN
Nov 25 15:49:18 unbound[24458:1] info: response for mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] info: reply from <mikulasske.cz.> 195.113.144.233#53
Nov 25 15:49:18 unbound[24458:1] info: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
mikulasske.cz. IN DNSKEY
;; ANSWER SECTION:
mikulasske.cz. 86400 IN DNSKEY 256 3 8 AwEAAbqo8jx7NbXoqKgswl+EwFPkHAhjdS6+JkhmFo8tygV2pTD7RYpU+5MBLZxxWmx8DwfqbTTFx+Hb/qeQr8GvgWWTStNFfAsR2jWg4sdXgX5PozjrCS3H7VAlCqyhlUOwwaiLu79DGudHrqRw
zGRT6/8jlfO5h74F4J7BfnaYMDzSBmSbUAL58I6jx9varHzulzq/eEblfxlFYxhGC+ubR95QLAkSMgqBTv/2jgt04e2daUmTDna1Rdn+cnfYf2Aj5O8ycrbPVQzdSqajfu/ohgsvCD7+xuDQ/7KE0O7BBX/2llZJI0BrRVjM36iwFAsXDTyL3Nnj/RQEGTZ3YH33
nL0= ;{id = 35946 (zsk), size = 2048b}
mikulasske.cz. 86400 IN DNSKEY 257 3 8 AwEAAdBISW2rX+jvm8tYslCVYi5k5z/91+nI9V6pNsN/YHpFfryuErF2SqAFahAzr2gkdhKH+PUmmZmMc3ZqjcN37vD17awEydCZtr/se2Ruz+FuRKQNab93cTOt/TvJdmUCunFREhA9rIjunjYq
lEAYqKWbsZ64qxUdU0NYNctl9bP59DbNjBELJaoSvrRs2DtJtJsZsCq5ASiVj6cI1Gu4Fox3SX5eKvReB7EjID7GNDVUpbd0ARQ3iVEFBl/V73+HtTCc/V7HxNggjhAQzUCrEOlhpM6pbNCaF8dpbqi4Y/zGIk47+icL0MNvd9YIrLFYFlgswDVfd/3uwReMXVHq
YFU= ;{id = 42592 (ksk), size = 2048b}
mikulasske.cz. 86400 IN RRSIG DNSKEY 8 2 86400 20160118212400 20151123212400 35946 mikulasske.cz. cfbl4FW0b4+kZ8bWspj28Z9g0WTgr6m2lZQh4qYvK+ENGRm2p2GD7p9ie4ItsRvWoSOYckk+Nn+Z4gd7j5pwEueH
rp85/i9b7ij1rT9I//gM3Q9T80TQuaNZVGilzQowN2DZMI4N7aDcoAkM2R4zeuSyhbxvepEAvK9p55QRr6PMq2l0xshMd6b/DK8biPEiP0Ym3+HrGCNNiNWnv2I3PYKJ2K/SIPjuQLIcY35kuXrTSxULYIj3hKbBrW/Wvr7YVYQHmd1CTwvLCidydCGqiEJcfNyI
aJDiqdQqTxOqU/oIccaGRqfZ7VHxjCJD5TfLuIGWMQ7Uns5GLQ/ZZfFzWw== ;{id = 35946}
mikulasske.cz. 86400 IN RRSIG DNSKEY 8 2 86400 20160118212400 20151123212400 42592 mikulasske.cz. LacHyWu+udogAFayox3wNFpCdW18uvREEykZ7xpAtw0UWdCPJKqZPbXsn+mRhn9Rvg49JAy0DZUk7pwmCVrbtlck
6Q63l2iR36xyxr/Kq20hKfCn23JX6lVdnFxyqz4Uqc1h0sPm61PeGnt335fFenj51Px6+ePKpizY3D9NtPBWuKao3A+klGvShqRknwTAdsyYa43C7ZA4cUZz2Sbm6ZtvN8IeNHL/jw1H0z9r5lW/xhBWSqjP7duXRflGDnL+WOzYd+CPIHSuDy9NiZo1V/OvpXHc
8QFlXGYPq8+YWZBDwnt2Hal1bH50hxz1jUUfJVK+uwSrI3a9pDqWT7QE9g== ;{id = 42592}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 1185
Nov 25 15:49:18 unbound[24458:1] debug: iter_handle processing q with state QUERY RESPONSE STATE
Nov 25 15:49:18 unbound[24458:1] info: query response was ANSWER
Nov 25 15:49:18 unbound[24458:1] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Nov 25 15:49:18 unbound[24458:1] info: finishing processing for mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: mesh_run: iterator module exit state is module_finished
Nov 25 15:49:18 unbound[24458:1] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Nov 25 15:49:18 unbound[24458:1] info: validator operate: query mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: validator: nextmodule returned
Nov 25 15:49:18 unbound[24458:1] debug: not validating response due to CD bit
Nov 25 15:49:18 unbound[24458:1] debug: mesh_run: validator module exit state is module_finished
Nov 25 15:49:18 unbound[24458:1] info: validator: inform_super, sub is mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] info: super is www.mikulasske.cz. A IN
Nov 25 15:49:18 unbound[24458:1] debug: attempt DS match algo 8 keytag 42592
Nov 25 15:49:18 unbound[24458:1] debug: DS match digest ok, trying signature
Nov 25 15:49:18 unbound[24458:1] debug: Failed to match any usable DS to a DNSKEY.
Nov 25 15:49:18 unbound[24458:1] debug: blacklist ip4 195.113.226.123 port 53 (len 16)
Nov 25 15:49:18 unbound[24458:1] debug: blacklist cache
Nov 25 15:49:18 unbound[24458:1] debug: blacklist add ip4 195.113.144.233 port 53 (len 16)
Nov 25 15:49:18 unbound[24458:1] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
Nov 25 15:49:18 unbound[24458:1] info: validator operate: query www.mikulasske.cz. A IN
Nov 25 15:49:18 unbound[24458:1] debug: val handle processing q with state VAL_FINDKEY_STATE
Nov 25 15:49:18 unbound[24458:1] info: validator: FindKey www.mikulasske.cz. A IN
Nov 25 15:49:18 unbound[24458:1] info: current keyname cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] info: target keyname mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: striplab 0
Nov 25 15:49:18 unbound[24458:1] info: next keyname mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] info: DS RRset mikulasske.cz. DS IN
Nov 25 15:49:18 unbound[24458:1] info: generate request mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: mesh_run: validator module exit state is module_wait_subquery
Nov 25 15:49:18 unbound[24458:1] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
Nov 25 15:49:18 unbound[24458:1] info: validator operate: query mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: validator: pass to next module
Nov 25 15:49:18 unbound[24458:1] debug: mesh_run: validator module exit state is module_wait_module
Nov 25 15:49:18 unbound[24458:1] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Nov 25 15:49:18 unbound[24458:1] debug: process_request: new external request event
Nov 25 15:49:18 unbound[24458:1] debug: iter_handle processing q with state INIT REQUEST STATE
Nov 25 15:49:18 unbound[24458:1] info: resolving mikulasske.cz. DNSKEY IN
Nov 25 15:49:18 unbound[24458:1] debug: request has dependency depth of 0
Nov 25 15:49:18 unbound[24458:1] debug: cache blacklisted, going to the network
Nov 25 15:49:18 unbound[24458:1] debug: cache delegation returns delegpt
Nov 25 15:49:18 unbound[24458:1] info: DelegationPoint<mikulasske.cz.>: 2 names (2 missing), 2 addrs (0 result, 2 avail) cacheNS
Nov 25 15:49:18 unbound[24458:1] info: ns.mikulasske.cz. A
Nov 25 15:49:18 unbound[24458:1] info: ns.ces.net. A
Nov 25 15:49:18 unbound[24458:1] debug: ip4 195.113.144.233 port 53 (len 16)
Nov 25 15:49:18 unbound[24458:1] debug: ip4 195.113.226.123 port 53 (len 16)
Nov 25 15:49:18 unbound[24458:1] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Nov 25 15:49:18 unbound[24458:1] info: resolving (init part 2): mikulasske.cz. DNSKEY IN
I am not maintaining mikulasske.cz, just resolving queries. These findings are based on a customer’s complain.
Are some options regarding DNSSEC different in 1.4.22 and 1.5.6?
Thanks
Ales