Domain does not validate

Fri May 28 07:34:18 UTC 2021

> Am 27.05.2021 um 23:00 schrieb Tony Finch <dot at dotat.at>:
> 
> Rainer Duffner via Unbound-users <unbound-users at lists.nlnetlabs.nl> wrote:
>> 
>> I have a setup where unbound is behind BIND 9.11 (due to RPZ handling).
>> 
>> In this setup, unbound cannot resolve one particular domain: nkb.ch due to DNSSEC failure.
>> 
>> However, BIND does correctly resolve the domain.
> 
> Well, dnsviz agrees with unbound that the zone's DS RRset doesn't match
> its DNSKEY RRset. https://dnsviz.net/d/nkb.ch/dnssec/

Ah, OK.

The interesting thing is that Verisign Labs’ DNSSEC-Analyzer thinks it’s OK:

https://dnssec-analyzer.verisignlabs.com/nkb.ch

> 
> It looks like your BIND upstream is not configured to validate (i.e. its
> configuration lacks `dnssec-validate auto;`) because your logs say that
> the response to unbound's nkb.ch DS query did not have the "ad"
> (authenticated data) bit set.
> 
> So I think both BIND and Unbound are correct, but their cnofigurations
> disagree about what is correct.

I had dnssec-validation set to „yes“, which I now realize was a mistake...

When I set it to „auto“, it actually does accept the data sent.

May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 192.168.1.60 nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0RDd mod1 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: nkb.ch.	IN	MX  ;; ANSWER SECTION: nkb.ch.	3600	IN	MX	10 mail10.nkb.ch. nkb.ch.	3600	IN	MX	20 mail20.nkb.ch. nkb.ch.	3600	IN	RRSIG	MX 8 2 3600 20210613164235 20210514154235 24028 nkb.ch. ZgJH1vLzwylFlPTHHgmwpSUwYy76kqtYfwXS5Tao5oh3X5eTv1jSkPpvx6lQM573c4esITnytdwJmOh/pxrcGYQSq2u9EM2jrCswVNiV5dHTVMVCKTxtbu51UmHdD+xBuf2mZbsaPx+xvLbDzgKEUJ1iDEZvvGR4RjJ+cmaOsr0= ;{id = 24028}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 236
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: signer is nkb.ch. TYPE0 CLASS0
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: prime trust anchor
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate keytag query _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 3 recursion states (1 with reply, 1 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1vRDd mod1  _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 2RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr aa rd ra ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: .	IN	DNSKEY  ;; ANSWER SECTION: .	86400	IN	DNSKEY	257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b} .	86400	IN	DNSKEY	256 3 8 AwEAAa+HvD7XXjmL+1htThUQyZW7oWGnjzKHJASg3TSR5Bmu5LfnSVW7fxqZa2oAYo2ionIQWyqAj/loApzg8GNMhyIibftPJso54uWRQ2GaoMrwLD5SLu676kf7urJq6nqdjNC0aJM/C888li69lVH6tiu2tZm1NH3cmgfnMUJpD60bsrDUqs7XwftmNkdkHa4ltQbM3UNPyfTaNBQYoH3wpOpSjdk3tyDRnreBO6Idrw+DGf/rve4sL3qiSaXfYIkcwAwozxR34iHU5dbCDs8S6FmZYhoSVKVgNSUkudxhd9/6RrZkYRgvwRsQXl3UwsacU1DsXcORqIC+7NlQ6M2OJVU= ;{id = 14631 (zsk), size = 2048b} .	86400	IN	RRSIG	DNSKEY 8 0 172800 20210611000000 20210521000000 20326 . cS+Q/Fz7GGC2l/Mlv6LCuawcezxDVnljzhpSlQNxdjAAaCcVxc+tq7DjexnuxktXsK6wlxTl3hYjkqQDHTsEsgKwgC5WkFj+YDbjwYIICrnJV6AmMgmmwNQKJiZtTcDoZMYbrpWgT7grKKD3gIJlFy+xHTG2Nb/YYZqbDqxTUYslac1tkB2/AVC94Y5Hp35/rUfsjGUfLYIjC/vfjJ8tnLmOo2nmV2h6gznllygibh4mDB6thGd4M0X+rTtWFADXLwTLttw8Y3658tyxboTh/94CI2OESqKXvxHG9SKjezs0qhQTQxSoHS7mtHHNMpLAZSyeABl1Dx5Id1sJ1YeDMg== ;{id = 20326}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 853
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: inform_super, sub is . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: super is nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: autotrust process for . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validate keys with anchor(DS): sec_status_secure
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: Successfully primed trust anchor . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: FindKey nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: current keyname . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: target keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: next keyname ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 3 recursion states (1 with reply, 1 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1vRDd mod1  _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 2RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0 ;; flags: qr aa rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 4, ADDITIONAL: 0  ;; QUESTION SECTION: _ta-4f66.	IN	NULL  ;; ANSWER SECTION:  ;; AUTHORITY SECTION: .	3600	IN	SOA	a.root-servers.net. nstld.verisign-grs.com. 2021052702 1800 900 604800 86400 .	86400	IN	RRSIG	SOA 8 0 86400 20210609170000 20210527160000 14631 . QjcjEW6Eh34N85sYcqh6ik7feooxrEBgszfwoMuIHVTkjHH03rD7T4/7PZq3kGM0Ie5jm52q0kQz+NXApL5Vo3cArbZy7lvNPgDhtkadFw8sMSM98eUBDhBPMyhw4R99frCRfoNFoEUxCw8nubIwa6DcN/rAsw0qZE9alwyFuXU+NLuPDaFIPi4rYu+SsXs8mkfFD++H7EDVOjjw95zuPl7CiPZidXWClXTENDp+JIP4XOL1cul/7P0yk11agaCwvl8SyBZR8uv/BOirEWrBYG2N4zMLh9uHshtsjYeHGdlTmCEI1KjJEGYRjVa8jAbK/ldZ+6ibzaZXx0QaEZWRfg== ;{id = 14631} .	86400	IN	NSEC	aaa. NS SOA RRSIG NSEC DNSKEY .	86400	IN	RRSIG	NSEC 8 0 86400 20210609170000 20210527160000 14631 . rWNai11jly79N1FDc5ctgVlr6Pg93S8LABb1h3kV3HTTHVNNyKIQPrmW+XPCV8jj3rvqfcdrhptBtALZKJl/Xd2kvEwt8u78OtXgJobIu7OlKGORk7woD3njCczL6vZS47MjsEJLG+bPXN2klPTMeISs2P30q/bIMnLPLpcf2wP7z5GQdg04nzk1eLtgZ2cfcsHqRUlIGgOnYdvRtew3oDndySW7p0Hqbpq4BMaSHeUBP1kXqipuTfCk5YM9o9myWowxhT3IPw8YeOUSLC2W+tl3AAzJz4Uz4/y7EmVnWLMaDbJWnRb6L05NLBWese7pTlucR9RPAxVbxwKEO8eFvg== ;{id = 14631}  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 698
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was NXDOMAIN ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query _ta-4f66. NULL IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr aa rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: ch.	IN	DS  ;; ANSWER SECTION: ch.	86400	IN	DS	1053 13 2 94D834BEF7536BFE6ECB4682E1151BDD4882CA12C6DB2C1AA64CB0E9D4DA5222 ch.	86400	IN	RRSIG	DS 8 1 86400 20210609170000 20210527160000 14631 . pjFTtU0THKLd5H49lVaXaiuCl65ApXZPkNs/ywzD2CyDpOeRpBdLImb67xWLQsqH+ZyPTAu/KXs3zEI2UV8YA10Dzv9DEMjbnje8tzmOZGYTfgTDQAkirkwzWhFmPoldYnb9De83hf1ZxF4PEOW5ehfNerwQyjZmXMZPzJEVLVYTKu3wlfISqWUk3NLxUbP9GJHN/xfcmglJO2eeJWrwDf0MP/2IYcKWi/j/O2df5wuJK/nk3tVf84u2a2wSo/i5BT/ZPvRuRf5E0EsrWGOvyh3Mk3dcVHk/l5J3qb3EWZQMgNPNxCpZiduqNpDna2/k/N6s94x8Dt+DpK+x7Ipxuw== ;{id = 14631}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 355
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: inform_super, sub is ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: super is nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: verify rrset ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validated DS ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: FindKey nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: current keyname . DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: target keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: next keyname ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DS RRset ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: ch.	IN	DNSKEY  ;; ANSWER SECTION: ch.	86400	IN	DNSKEY	256 3 13 mkq7fKwtqE63+fZOXLQm/A3KwERRApDGSKRBxaD6RNQeJRrDRfD1F3KmFyc0K5BbQ1aj3mLGOF5Tf4hBS4ANjQ== ;{id = 31174 (zsk), size = 256b} ch.	86400	IN	DNSKEY	257 3 13 kr4o4HQBltkJbi/uQ03HU9DY4eKY9gVHyHJk/Qw1ZRYeCb/QMQ8hx0gN5o0lTBEqO/H5DwCWxM33aUwBBZostw== ;{id = 1053 (ksk), size = 256b} ch.	86400	IN	DNSKEY	256 3 13 SMCx7OwqldNbwYa1KPvOC1JYYCg650Pr3k0tte1e1v4DBBI7fr8r86u3GA/hZH54OvDGtEdaCvQFH9ATvulBCQ== ;{id = 26777 (zsk), size = 256b} ch.	86400	IN	RRSIG	DNSKEY 13 1 86400 20210624100909 20210509090909 1053 ch. ehmogXXEoOHr09MFAThv0Q4QT9vP3+TUU8U9P8MSDq6oltC97ROJdKqokXqV62hJGvWYb6k3JYDR2KCGVxc19g== ;{id = 1053}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 358
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: inform_super, sub is ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: super is nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validated DNSKEY ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: FindKey nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: current keyname ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: target keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: next keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DS RRset ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: nkb.ch.	IN	DS  ;; ANSWER SECTION: nkb.ch.	3600	IN	DS	35452 8 2 BD1476418FB2ACC3578C8041272975686C960C706CF551A82A17D38E904AE43B nkb.ch.	3600	IN	RRSIG	DS 13 2 3600 20210623104441 20210524100200 31174 ch. i+EMIS2Tl+aWG41eJyGZ3OKvhNpY/PkgFPU45MxhPGqPMXjWC1+xyV9VRIYYzWqKcEEDps2MjyEui6+ax/x8gw== ;{id = 31174}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 170
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: inform_super, sub is nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: super is nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: verify rrset nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validated DS nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: FindKey nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: current keyname ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: target keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: next keyname nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DS RRset nkb.ch. DS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: generate request nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: resolving nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: processQueryTargets: nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: sending query: nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 0vRDCD mod1  nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: 1RDdc mod0 rep nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: iterator operate: query nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: scrub for . NS IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: response for nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: reply from <.> 192.168.1.61#53
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0 ;; flags: qr rd ra ; QUERY: 1, ANSWER: 5, AUTHORITY: 0, ADDITIONAL: 0  ;; QUESTION SECTION: nkb.ch.	IN	DNSKEY  ;; ANSWER SECTION: nkb.ch.	3600	IN	DNSKEY	257 3 8 AwEAAcj3MiPiuxBUJ7UjOwBmmGZK6jBpctEVuF2gID+gS8TOedeOCqh7hgyI2hl0YO9094urxi68zEQWIQWIVzmvD6ThdhQgAxYX3q8jAAvAgH29VYt08AaFeKEHw1uR65VGefHtacJKQLQG5E0ysz+Sq9GPVA7dha2MO2EBPJINVVf5hguCMLzq0d7r2vMGStYorR/FkquUxLz400yIM+yU91K8tjEAjBA32zT7C1uiPIjSpR3AZ/eevv6NA5heZSZBkG1+d8Uhgs4hwU6gnAMVXz+Z2kmlOV7Iyv15GyzzpupyPRvEV+48raD2amKFf6nr1Gg7PWvGYlWxK/3zE83gMg0= ;{id = 35452 (ksk), size = 2048b} nkb.ch.	3600	IN	DNSKEY	256 3 8 AwEAAau9V1gNmiuA7xBMQKSKTOUEZ6fQUQXSHTouGjDMpeCxB8fjYTk7lImWvJQXu9Zf5Pc6oVoQNxUGhm62bIuwCHzXpGJALRWQwVMYTmWcqq7Pxu5nfShNbfNEhf7f9Yien2nfZVQ5T5LnKAaqRarRCJl0mlhJs44h7K5IDwF5vnk1 ;{id = 50191 (zsk), size = 1024b} nkb.ch.	3600	IN	DNSKEY	256 3 8 AwEAAbX4dsGpdpbFnAQUTNLsen8hV+fm008/twYyi5hKv7hqgxJv41PEWCNHW8+WsgddgBboQd8pkPGI8r0O/6hWeNwvPp1YCYXr0P60YMmtk4QUBQnh6UhsHsGXSYzMRShzVpX6obRRej5+nzqQYY8l4y8GxBdVwz2dMYGBIMaSqUPh ;{id = 24028 (zsk), size = 1024b} nkb.ch.	3600	IN	RRSIG	DNSKEY 8 2 3600 20210602114858 20210526104858 35452 nkb.ch. fOu2tY1NPYM5GjqV96Zx9N+jSz0Wmpwc0GJEGKVGXIGX9rPTted+apTwAvBwdMI8bFFM3FXCw9LD2NnMSX3NR+7qYwqCrwpafjuD8S0goM2bJu+HqTTDwnjljogpPok2hyfSyLS2vAIlVCDokNefE+ZjYZ4aMmoQ5tTPA1qHb0fOP1HnVcX7ms4F4z4i2p2XIfhArH8FwCA8PxuxOE8Qh0WrgBZ6T6/wQZdTRE6rBoHQQJPqmYKUlROSQ+KH3At6PZgZee/r4zIY3IdXjjUQPjGTxgWeGj/D+ZQz85myPkiBcuPMLD5EXlhi6kyb4KqDwBwveWMIL+vxAKcqtzw1eA== ;{id = 35452} nkb.ch.	3600	IN	RRSIG	DNSKEY 8 2 3600 20210625114858 20210526104858 24028 nkb.ch. sVCV0z2iNkX5hGHv707SiLKZM4BOMkhk4hJq0bDSwboz46TJuMrBcNXXKHNyrYC/XONsKwiobLG1ZtegA5fWh/TrnnzZcFTNleqYRwBNeXS1cwybKXiuCwwIc9ukIadDATv37hzo07NfaWQ2EP24YHUb4EJWb7RJitLa1jVnuRw= ;{id = 24028}  ;; AUTHORITY SECTION:  ;; ADDITIONAL SECTION: ;; MSG SIZE  rcvd: 1056
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: query response was ANSWER
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: finishing processing for nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: inform_super, sub is nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: super is nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validated DNSKEY nkb.ch. DNSKEY IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator operate: query nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validator: FindKey nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: verify rrset nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validate(positive): sec_status_secure
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: validation success nkb.ch. MX IN
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: average recursion processing time 0.275064 sec
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: histogram of recursion processing times
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: [25%]=0 median[50%]=0 [75%]=0
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info: lower(secs) upper(secs) recursions
May 28 09:22:15 bind-unbound-test unbound[99493]: [99493:0] info:    0.262144    0.524288 1

Maybe this is because of this?

https://ednscomp.isc.org/ednscomp/55539d451a

Regards,
Rainer