Unbound (sometimes) fails to resolve expired entries

Sebastian_Andrzej_Si · June 12, 2020, 12:41pm

I'm running here unbound 1.9.0-2+deb10u2 (1.9.0 + 3 fixes on top).

I added a TXT record for testing. That record resolves fine on the first
query which is fetched from the upstream DNS-server. Once TTL of the
record expires the record is fetched again and the TTL is 1h.
Sometimes I see NXDOMAIN reply with the SOA record instead. Looking at
the query time, unbound did something. Looking at the TTL it appears
that unbound thinks that this record is not existing based on DNSSEC.

Here is a sample:

;small._testentry.breakpoint.cc. IN TXT

;; ANSWER SECTION:
small._testentry.breakpoint.cc. 1533 IN TXT "23F678951D8D4 2 535BD23F678951D8D67FF18184AD1E4DCDA4718A1E0614DB4263463778769B1FC240A3586668CA62472070243CD154460B3BF3B16E7F808C8DD3362F 8A329BEA67Fa3529ac6407975eceba96aed90948fbd8b34753fF18184AD1E4DCDA4718A1E0614DB45B8B17CD8076DEBF5647C6E18C516DDF3D9D209" "C263463778769B1FC240A"
small._testentry.breakpoint.cc. 1533 IN RRSIG TXT 8 4 3600 20200625000000 20200604000000 17836 breakpoint.cc. faJFAX0IuV8pefY7TULpfeD3Z2LaZVTTaazjfp5ef4frZlwdHy+3P5NX jfT/X8+KVvP8zkKV eq1Cqz/VR74Ff99fNcW7wnwM6bYHDWd2fR7E0qhO bQ4QEGrA0chFKAYKc71Jhqv9qduYzQiPkJWB1GLo2YCzLP6wPWlV0S0E 0TI=

;; Query time: 0 msec
;; WHEN: Fr Jun 12 12:51:50 CEST 2020

matching unbound log is:

Jun 12 12:51:50 unbound[909:1] query: 1.1.1.1 small._testentry.breakpoint.cc. TXT IN
Jun 12 12:51:50 unbound[909:1] reply: 1.1.1.1 small._testentry.breakpoint.cc. TXT IN NOERROR 0.000000 1 522

The follwing query (after expired TTL) failed:

; <<>> DiG 9.11.5-P4-5.1+deb10u1-Debian <<>> txt small._testentry.breakpoint.cc +dnssec
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 19288
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 0, AUTHORITY: 8, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;small._testentry.breakpoint.cc. IN TXT

;; AUTHORITY SECTION:
breakpoint.cc. 3600 IN SOA ns.domrobot.com. hostmaster.inwx.de. 2020061002 10800 3600 604800 3600
breakpoint.cc. 3600 IN RRSIG SOA 8 2 86400 20200625000000 20200604000000 17836 breakpoint.cc. iTHewyyuXaKwOrvsCg9u0NpdB3VuwzxZxPsK/QumBLRYVkKLGmoaC4ZJ 9f+QUnHkWD9XxPp e4KMHcQJLFjJq7ps9wVYimHk+1a9jlX253OrOpQcD bUWU0eP0URr3vabert76Z/qAWD/k/BMky0b49RIrvtR1y7w8tacGs4Uy M6g=
qbhcs6199or0dl4i4bar1i7n3cc1vqpn.breakpoint.cc. 216 IN NSEC3 1 0 1 AB S83Q2OVGP0E7FHQJNV7J5V5LB6CSPEFN A NS SOA MX TXT AAAA SSHFP RRSIG DNSKEY NSEC3PARAM CAA
qbhcs6199or0dl4i4bar1i7n3cc1vqpn.breakpoint.cc. 216 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. G24QTyKjAy5gL01kF5PEEm42BazFCb+a13hWnUxwwUpIjxTXay7sY5Ds y IeKrPTJoP653S1T3yDPf8pwdS+ed5somE/aH1bk5bkaTQhQfKCEuQeD cq4lAsjb7YSTYtkQn2BDW2GxlX5D2GE35BpnaFnN89z854ah+nFKNBQj WC0=
dn0b8grfgs3s9r91kclagbqcjsu75kf2.breakpoint.cc. 3600 IN NSEC3 1 0 1 AB F6GSHJ9K6R5D0APP3V0QD425LOQ2OL3T CNAME RRSIG
dn0b8grfgs3s9r91kclagbqcjsu75kf2.breakpoint.cc. 3600 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. KKuqLp6vlq3KGp8pffg+MfTYIJb0KtoGLQYqNn/iPw8IfiZRHEwohaAu s1RDenaCFE/0Y4rjljBq0G1Gg2AF1F0foQTyTmnp6O3Aq+7Wd/HR/+lc AbPgXrNOIWc7PxztssBxbH5KNtLOkuy4UpRhABJ6O66rSZMdNJHNq4/X LgA=
s83q2ovgp0e7fhqjnv7j5v5lb6cspefn.breakpoint.cc. 216 IN NSEC3 1 0 1 AB TCBNVRBS8UKG82HKM6DIC67R68OEV8H6 MX TXT RRSIG
s83q2ovgp0e7fhqjnv7j5v5lb6cspefn.breakpoint.cc. 216 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. QhYmntdlFwOOLwxHeentJTGgbFIE+AVeiEuyak2G7W9bSwCm5S2IoAYR i d9gdFry914xxbgZ1USpInclp/0Di+ZBb9YBID5XUIbTz41AnlVGtuTV sd1J9m8URjGmlgTVElSs7PskcMBAvtri+OAIlHRDQbo/2HTJ3pH3nadu jgw=

;; Query time: 58 msec
;; WHEN: Fr Jun 12 13:20:51 CEST 2020
;; MSG SIZE rcvd: 1064

The matching unbound.log at that time:

Jun 12 13:20:51 unbound[909:0] query: 1.1.1.1 small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: resolving small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (1 missing), 9 addrs (0 result, 9 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. A
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: resolving (init part 2): small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: resolving (init part 3): small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: processQueryTargets: small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (1 missing), 9 addrs (0 result, 9 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. A
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: new target ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: sending query: _testentry.breakpoint.cc. A IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: resolving ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
;; QUESTION SECTION:
ns.domrobot.org. IN AAAA

;; ANSWER SECTION:

;; AUTHORITY SECTION:
domrobot.org. 3408 IN SOA ns.domrobot.com. hostmaster.inwx.de. 2020042700 10800 3600 604800 3600

;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 102

Jun 12 13:20:51 unbound[909:0] info: finishing processing for ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: processTargetResponse ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: processTargetResponse super small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: processQueryTargets: small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (0 missing), 9 addrs (9 result, 0 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 2155 recursion replies sent, 0 replies dropped, 0 states jostled out
Jun 12 13:20:51 unbound[909:0] info: average recursion processing time 0.146111 sec
Jun 12 13:20:51 unbound[909:0] info: 0RDd mod2 rep small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: scrub for breakpoint.cc. NS IN
Jun 12 13:20:51 unbound[909:0] info: response for small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: reply from <breakpoint.cc.> 46.165.212.97#53
Jun 12 13:20:51 unbound[909:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 0, AUTHORITY: 8, ADDITIONAL: 0
;; QUESTION SECTION:
_testentry.breakpoint.cc. IN A

;; ANSWER SECTION:

;; AUTHORITY SECTION:
breakpoint.cc. 3600 IN SOA ns.domrobot.com. hostmaster.inwx.de. 2020061002 10800 3600 604800 3600
breakpoint.cc. 3600 IN RRSIG SOA 8 2 86400 20200625000000 20200604000000 17836 breakpoint.cc. iTHewyyuXaKwOrvsCg9u0NpdB3VuwzxZxPsK/QumBLRYVkKLGmoaC4ZJ9f+QUnHkWD9XxPpe4KMHcQJLFjJq7ps9wVYimHk+1a9jlX253OrOpQcDbUWU0eP0URr3vabert76Z/qAWD/k/BMky0b49RIrvtR1y7w8tacGs4UyM6g= ;{id = 17836}
qbhcs6199or0dl4i4bar1i7n3cc1vqpn.breakpoint.cc. 3600 IN NSEC3 1 0 1 AB s83q2ovgp0e7fhqjnv7j5v5lb6cspefn A NS SOA MX TXT AAAA SSHFP RRSIG DNSKEY NSEC3PARAM CAA
qbhcs6199or0dl4i4bar1i7n3cc1vqpn.breakpoint.cc. 3600 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. G24QTyKjAy5gL01kF5PEEm42BazFCb+a13hWnUxwwUpIjxTXay7sY5DsyIeKrPTJoP653S1T3yDPf8pwdS+ed5somE/aH1bk5bkaTQhQfKCEuQeDcq4lAsjb7YSTYtkQn2BDW2GxlX5D2GE35BpnaFnN89z854ah+nFKNBQjWC0= ;{id = 17836}
dn0b8grfgs3s9r91kclagbqcjsu75kf2.breakpoint.cc. 3600 IN NSEC3 1 0 1 AB f6gshj9k6r5d0app3v0qd425loq2ol3t CNAME RRSIG
dn0b8grfgs3s9r91kclagbqcjsu75kf2.breakpoint.cc. 3600 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. KKuqLp6vlq3KGp8pffg+MfTYIJb0KtoGLQYqNn/iPw8IfiZRHEwohaAus1RDenaCFE/0Y4rjljBq0G1Gg2AF1F0foQTyTmnp6O3Aq+7Wd/HR/+lcAbPgXrNOIWc7PxztssBxbH5KNtLOkuy4UpRhABJ6O66rSZMdNJHNq4/XLgA= ;{id = 17836}
s83q2ovgp0e7fhqjnv7j5v5lb6cspefn.breakpoint.cc. 3600 IN NSEC3 1 0 1 AB tcbnvrbs8ukg82hkm6dic67r68oev8h6 MX TXT RRSIG
s83q2ovgp0e7fhqjnv7j5v5lb6cspefn.breakpoint.cc. 3600 IN RRSIG NSEC3 8 3 3600 20200625000000 20200604000000 17836 breakpoint.cc. QhYmntdlFwOOLwxHeentJTGgbFIE+AVeiEuyak2G7W9bSwCm5S2IoAYRid9gdFry914xxbgZ1USpInclp/0Di+ZBb9YBID5XUIbTz41AnlVGtuTVsd1J9m8URjGmlgTVElSs7PskcMBAvtri+OAIlHRDQbo/2HTJ3pH3nadujgw= ;{id = 17836}

;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 1047

Jun 12 13:20:51 unbound[909:0] info: query response was NXDOMAIN ANSWER
Jun 12 13:20:51 unbound[909:0] info: finishing processing for small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: signer is breakpoint.cc. TYPE0 CLASS0
Jun 12 13:20:51 unbound[909:0] info: validator: FindKey small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: current keyname cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: target keyname breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: next keyname breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: verify rrset cached breakpoint.cc. DS IN
Jun 12 13:20:51 unbound[909:0] info: validated DS breakpoint.cc. DS IN
Jun 12 13:20:51 unbound[909:0] info: validator: FindKey small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: current keyname cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: target keyname breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: next keyname breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: DS RRset breakpoint.cc. DS IN
Jun 12 13:20:51 unbound[909:0] info: generate request breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: resolving breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (1 missing), 9 addrs (0 result, 9 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. A
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: resolving (init part 2): breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: resolving (init part 3): breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: processQueryTargets: breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (1 missing), 9 addrs (0 result, 9 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. A
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: new target ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: sending query: breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: resolving ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
;; QUESTION SECTION:
ns.domrobot.org. IN AAAA

;; ANSWER SECTION:

;; AUTHORITY SECTION:
domrobot.org. 3408 IN SOA ns.domrobot.com. hostmaster.inwx.de. 2020042700 10800 3600 604800 3600

;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 102

Jun 12 13:20:51 unbound[909:0] info: finishing processing for ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: processTargetResponse ns.domrobot.org. AAAA IN
Jun 12 13:20:51 unbound[909:0] info: processTargetResponse super breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: processQueryTargets: breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: DelegationPoint<breakpoint.cc.>: 5 names (0 missing), 9 addrs (9 result, 0 avail) cacheNS
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.biz. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.info. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.org. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.net. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: ns.domrobot.com. * A AAAA
Jun 12 13:20:51 unbound[909:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 2155 recursion replies sent, 0 replies dropped, 0 states jostled out
Jun 12 13:20:51 unbound[909:0] info: average recursion processing time 0.146111 sec
Jun 12 13:20:51 unbound[909:0] info: 0vRDCD mod2 breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: 1RDdc mod1 rep small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: iterator operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: scrub for breakpoint.cc. NS IN
Jun 12 13:20:51 unbound[909:0] info: response for breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: reply from <breakpoint.cc.> 176.97.158.104#53
Jun 12 13:20:51 unbound[909:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
breakpoint.cc. IN DNSKEY

;; ANSWER SECTION:
breakpoint.cc. 3600 IN DNSKEY 256 3 8 AwEAAaN8AgmIx2O3OkzW0YkqVSxC5nN/GafK40hkKb3JbYkpy7hPU1odw5Qcta6BZiuC1uUUOsDjMq8sbc+jt7iIBiwsCYqmM9biK0RGtYO3QT6G34SMpLhiqZpk2YsN7XThjVr8gm+Cz44Prp/rG8sR5EaKajsElzKh4HKgl3b3L22b ;{id = 17836 (zsk), size = 1024b}
breakpoint.cc. 3600 IN DNSKEY 257 3 8 AwEAAcXGzJMyf+B0H1flxTBJjyNou1EvXED6l7yGzHXlfbIh7mmnKco+yU6W0NFLQtcjotck+Uy7+jqb0PP3oiYT0JzGyaGNLSwZsu5Sgc7LG87c4V6zzuAkk+cm71zbEX5w3+XZANi9T6bzJVv2tpAg2VIjr50DCUzNJ3fE1csF7CeLOY1GCCBJF6FejKbzKFX4M4jApmNbPl3dZUs0SmBNiJxbGiKRn9drhpXDSVwhjrl20m6oh+lqz6kdQTHZ2wtS98FkyXcqMcklAaIMwFFPvb8ETPqDje7Hu5dNbWMegdfMYzfqv+bOlwBVLHrKy1LdbHma47K/O7axsnNzNOwJB8c= ;{id = 9361 (ksk), size = 2048b}
breakpoint.cc. 3600 IN RRSIG DNSKEY 8 2 3600 20200625000000 20200604000000 9361 breakpoint.cc. Dg5k0nHbX+7+hwbNdCJQgeWkEVLpNw0rX3tIn8uAnosJYISpxIkuQUC5HhDL0BIzcBWK/N329lHvJfvQs0g46ZMXYmu+GORx/lPj9+7byFcKz/bfxZoFf63SfVGXvXzC6nMmpcjp4ornqcPwAls6+zNdNmjBvo5kqC3D+yu7H22AcrlJdquEk5PMOBqhwHbP6rkFEPUbszw4mGWCedzUGbROn10mZSnWTBk3nOPrDCplV8s+dfLd4EWobuewMFD0BT/mZJb1+Kh9AQIenSXhvzYrzTHV+CWJMKemXs8j0+MbkmFLC29gFAHTAJ14I0uo+ABPptstcmpHxSMD46sA7w== ;{id = 9361}

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 756

Jun 12 13:20:51 unbound[909:0] info: query response was ANSWER
Jun 12 13:20:51 unbound[909:0] info: finishing processing for breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: validator: inform_super, sub is breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: super is small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: validated DNSKEY breakpoint.cc. DNSKEY IN
Jun 12 13:20:51 unbound[909:0] info: validator operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: validator: FindKey small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: verify rrset breakpoint.cc. SOA IN
Jun 12 13:20:51 unbound[909:0] info: verify rrset cached qbhcs6199or0dl4i4bar1i7n3cc1vqpn.breakpoint.cc. NSEC3 IN
Jun 12 13:20:51 unbound[909:0] info: verify rrset dn0b8grfgs3s9r91kclagbqcjsu75kf2.breakpoint.cc. NSEC3 IN
Jun 12 13:20:51 unbound[909:0] info: verify rrset cached s83q2ovgp0e7fhqjnv7j5v5lb6cspefn.breakpoint.cc. NSEC3 IN
Jun 12 13:20:51 unbound[909:0] info: start nsec3 nameerror proof, zone breakpoint.cc. TYPE0 CLASS0
Jun 12 13:20:51 unbound[909:0] info: ce candidate breakpoint.cc. TYPE0 CLASS0
Jun 12 13:20:51 unbound[909:0] info: nsec3 nameerror: proven ce= breakpoint.cc. TYPE0 CLASS0
Jun 12 13:20:51 unbound[909:0] info: validate(nxdomain): sec_status_secure
Jun 12 13:20:51 unbound[909:0] info: validation success small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] info: subnet operate: query small._testentry.breakpoint.cc. TXT IN
Jun 12 13:20:51 unbound[909:0] reply: 1.1.1.1 small._testentry.breakpoint.cc. TXT IN NXDOMAIN 0.056360 0 1064

Could this have something todo with "qname-minimisation: yes" ?

Sebastian

Wouter · June 12, 2020, 12:58pm

Hi Sebastian,

I'm running here unbound 1.9.0-2+deb10u2 (1.9.0 + 3 fixes on top).

Unbound can prove, at the last piece of your log, with DNSSEC, that
_testentry does not exist. With an NXDOMAIN proof. And because of
that, that means there are no names underneath it, hence it takes that
as the answer.

The config qname-minimisation and harden-below-nxdomain influence
unbound for it. You turn them off and unbound is less likely to fall
into this behaviour. But they are much better turned on, because they
provide nxdomain protection for unused root domains, and qname
minimisation is one of the few working privacy techniques.

Also there is an NXDOMAIN is really NXDOMAIN RFC standard out there,
that says this is how it should work.

That is broken is that you forgot to resign the zone after adding your
test record, hence the NSEC3 denial records prove it does not exist. If
unbound gets there records first, and is configured to do so, it infers
that your sample TXT record does not exist. If it sees the straight up
TXT record first, it looks like it exists, and this persists in the
cache for some time.

This happens because the zone is weird, eg. sign it again, or make an
unsigned delegation into the _testentry subzone. By making an unsigned
delegation, with nameserver NS entries, and then resigning.

Another quick workaround, if you really need it is to add the TXT record
as a local-data statement into unbound config. Unbound can parse the
same zoneformat as zonefiles have and then serves the local data before
it examines if it could be gotten in some other way.

Best regards, Wouter

heidnes · June 12, 2020, 1:24pm

I'm running here unbound 1.9.0-2+deb10u2 (1.9.0 + 3 fixes on top).

I added a TXT record for testing. That record resolves fine on the first
query which is fetched from the upstream DNS-server. Once TTL of the
record expires the record is fetched again and the TTL is 1h.
Sometimes I see NXDOMAIN reply with the SOA record instead. Looking at
the query time, unbound did something. Looking at the TTL it appears
that unbound thinks that this record is not existing based on DNSSEC.

Here is a sample:

> ;small._testentry.breakpoint.cc. IN TXT

https://dnsviz.net/d/small._testentry.breakpoint.cc/dnssec/

seems to indicate there are NSEC3 entries in the breakpoint.cc
zone which deny the existence of the quoted name.

Regards,

- Håvard

Sebastian_Andrzej_Si · June 12, 2020, 1:53pm

Hi Sebastian,

Hi Wouter,

> I'm running here unbound 1.9.0-2+deb10u2 (1.9.0 + 3 fixes on top).

Unbound can prove, at the last piece of your log, with DNSSEC, that
_testentry does not exist. With an NXDOMAIN proof. And because of
that, that means there are no names underneath it, hence it takes that
as the answer.

The config qname-minimisation and harden-below-nxdomain influence
unbound for it. You turn them off and unbound is less likely to fall
into this behaviour. But they are much better turned on, because they
provide nxdomain protection for unused root domains, and qname
minimisation is one of the few working privacy techniques.

Also there is an NXDOMAIN is really NXDOMAIN RFC standard out there,
that says this is how it should work.

Okay.

That is broken is that you forgot to resign the zone after adding your
test record, hence the NSEC3 denial records prove it does not exist. If
unbound gets there records first, and is configured to do so, it infers
that your sample TXT record does not exist. If it sees the straight up
TXT record first, it looks like it exists, and this persists in the
cache for some time.

This happens because the zone is weird, eg. sign it again, or make an
unsigned delegation into the _testentry subzone. By making an unsigned
delegation, with nameserver NS entries, and then resigning.

Another quick workaround, if you really need it is to add the TXT record
as a local-data statement into unbound config. Unbound can parse the
same zoneformat as zonefiles have and then serves the local data before
it examines if it could be gotten in some other way.

I don't operate the DNS server so I will complain to the operator then.
I was going to setup domainkey support and noticed that it sometimes
failes to verify and then I noticed that the DNS records is missing.
Then I noticed this only on my unbounds nodes after setting up Test.

Thank you for the verbose explanation Wouter.

Best regards, Wouter

Sebastian

Sebastian_Andrzej_Si · June 12, 2020, 1:54pm

> > ;small._testentry.breakpoint.cc. IN TXT

https://dnsviz.net/d/small._testentry.breakpoint.cc/dnssec/

seems to indicate there are NSEC3 entries in the breakpoint.cc
zone which deny the existence of the quoted name.

That link is handy. Thank you.

Regards,

- Håvard

Sebastian