Resolver does not appear to attempt qname minimization after first resolution.

9.16.13-Ubuntu

Installed from ppa:isc/bind

Afternoon. We are trying to validate that Bind is following qname minimization using the test provided by NLnet Labs. Their test is a TXT record that is hosted at a.b.qnamemin-test.internet.nl. We are not sure if we are misunderstanding what qname-minimization should be doing or if this is the intended actions of the resolver.

This test was run on a clean ubuntu 18.04VM with the defaults for bind beyond having logging to file. qname-minimization defaults to "relaxed". We have also tried this with "strict" set but the output below is with the default. Apology for me editing the debug output, and I can provide full log if wanted. But I think I kept what was important here.

The first request for this TXT record follows the proper minimization path.

27-Apr-2021 20:57:43.948 resolver: debug 1: fetch: a.b.qnamemin-test.internet.nl/TXT
27-Apr-2021 20:57:43.948 resolver: debug 10: log_ns_ttl: fctx 0x7ff8a4015cd0: fctx_create: a.b.qnamemin-test.internet.nl (in '.'?): 1 518365
27-Apr-2021 20:57:43.948 resolver: debug 5: QNAME minimization -  minimized, qmintype 2 qminname nl
27-Apr-2021 20:57:43.948 resolver: debug 1: fetch: nl/NS
27-Apr-2021 20:57:44.184 resolver: debug 1: fetch: nl/DNSKEY
27-Apr-2021 20:57:44.280 resolver: debug 1: fetch: internet.nl/NS
27-Apr-2021 20:57:44.432 resolver: debug 1: fetch: internet.nl/DNSKEY
27-Apr-2021 20:57:44.604 resolver: debug 1: fetch: qnamemin-test.internet.nl/NS
27-Apr-2021 20:57:44.868 resolver: debug 1: fetch: qnamemin-test.internet.nl/DS
27-Apr-2021 20:57:44.960 resolver: debug 1: fetch: b.qnamemin-test.internet.nl/NS

Part of the logic of the NLnet Labs test is that the NS query for b.qnamemin-test.internet.nl will send you to a different server for the final record than if you request the non-minimized QNAME. The NS record returned sends us to 185.49.140.63 for our TXT record lookup. Both this NS record, and the next TXT record with the "HOORAY" message have 10 second TTLs.

27-Apr-2021 20:57:44.960 resolver: debug 10: log_ns_ttl: fctx 0x7ff89802c180: fctx_create: b.qnamemin-test.internet.nl (in 'qnamemin-test.internet.nl'?): 1 11
27-Apr-2021 20:57:45.128 resolver: debug 10: received packet from 185.49.140.61#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  34670
;; flags: qr; QUESTION: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
;; QUESTION SECTION:
;b.qnamemin-test.internet.nl.	IN	NS

;; AUTHORITY SECTION:
;b.qnamemin-test.internet.nl. 10	IN	NS	ns.b.qnamemin-test.internet.nl.

;; ADDITIONAL SECTION:
;ns.b.qnamemin-test.internet.nl.	10 IN	A	185.49.140.63
;ns.b.qnamemin-test.internet.nl.	10 IN	AAAA	2a04:b900::8:0:0:63


27-Apr-2021 20:57:45.296 resolver: debug 3: fctx 0x7ff8a4015cd0(a.b.qnamemin-test.internet.nl/TXT): createfind for 127.0.0.1#34294/56587 - success
27-Apr-2021 20:57:45.468 resolver: debug 10: received packet from 185.49.140.63#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  57792
;; flags: qr aa; QUESTION: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: 4c8bb7557733e1ae0100000060887ac9de1433595eeeb769
;; QUESTION SECTION:
;a.b.qnamemin-test.internet.nl.	IN	TXT

;; ANSWER SECTION:
;a.b.qnamemin-test.internet.nl. 10 IN	TXT	"HOORAY - QNAME minimisation is enabled on your resolver :)!"

;; AUTHORITY SECTION:
;a.b.qnamemin-test.internet.nl. 10 IN	NS	ns.a.b.qnamemin-test.internet.nl.

;; ADDITIONAL SECTION:
;ns.a.b.qnamemin-test.internet.nl. 10 IN	A	185.49.140.63
;ns.a.b.qnamemin-test.internet.nl. 10 IN	AAAA	2a04:b900::8:0:0:63

While in cache, BIND serves the "HOORAY" TXT record. When that record, and the b.qnamemin-test.internet.nl NS record's TTL expires however, it appears that BIND does not attempt minimization on the next request.

27-Apr-2021 20:57:45.468 database: debug 1: delete_node(): 0x7ff8af6b18d0 a.b.qnamemin-test.internet.nl (bucket 27)
27-Apr-2021 20:57:45.468 database: debug 1: delete_node(): 0x7ff8af6b18d0 a.b.qnamemin-test.internet.nl (bucket 27)
27-Apr-2021 20:57:45.468 database: debug 1: delete_node(): 0x7ff8af6b18d0 ns.a.b.qnamemin-test.internet.nl (bucket 5)
27-Apr-2021 20:57:59.981 resolver: debug 1: fetch: a.b.qnamemin-test.internet.nl/TXT
27-Apr-2021 20:57:59.981 resolver: debug 10: log_ns_ttl: fctx 0x7ff8a0002cb0: fctx_create: a.b.qnamemin-test.internet.nl (in 'internet.nl'?): 1 3585
27-Apr-2021 20:57:59.981 resolver: debug 5: QNAME minimization -  minimized, qmintype 2 qminname qnamemin-test.internet.nl

This looks proper so far, the largest suffix we have for the QNAME in cache is internet.nl, which has a 1 hour TTL. So we do the next step, requesting the NS for qnamemin-test.internet.nl.

27-Apr-2021 20:58:00.157 resolver: debug 10: log_ns_ttl: fctx 0x7ff89802c180: rctx_answer_none: qnamemin-test.internet.nl (in 'internet.nl'?): 1 3585
27-Apr-2021 20:58:00.157 resolver: debug 10: log_ns_ttl: fctx 0x7ff89802c180: DELEGATION: qnamemin-test.internet.nl (in 'qnamemin-test.internet.nl'?): 0 3585
27-Apr-2021 20:58:00.157 database: debug 5: dns_adb_destroyfind on find 0x7ff8aeda7210
27-Apr-2021 20:58:00.157 database: debug 5: dns_adb_destroyfind on find 0x7ff8aedaed10
27-Apr-2021 20:58:00.157 database: debug 5: expiring v4 for name 0x7ff8aedb13a0
27-Apr-2021 20:58:00.157 database: debug 5: dns_adb_createfind: found A for name ns.qnamemin-test.internet.nl (0x7ff8aedb13a0) in db
27-Apr-2021 20:58:00.157 resolver: debug 3: fctx 0x7ff89802c180(qnamemin-test.internet.nl/NS): createfind for <unknown>/0 - success
27-Apr-2021 20:58:00.329 resolver: debug 10: received packet from 185.49.140.61#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  13741
;; flags: qr aa; QUESTION: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
;; QUESTION SECTION:
;qnamemin-test.internet.nl.	IN	NS

;; ANSWER SECTION:
;qnamemin-test.internet.nl. 10	IN	NS	ns.qnamemin-test.internet.nl.

;; ADDITIONAL SECTION:
;ns.qnamemin-test.internet.nl. 10 IN	A	185.49.140.61
;ns.qnamemin-test.internet.nl. 10 IN	AAAA	2a04:b900::8:0:0:61

The resolver's next step should be to query for the NS of b.qnamein-test.internet.nl. That's where we would be sent to the server hosting the "HOORAY" TXT record, on 185.49.140.63.

Instead, BIND asks the TXT record a.b.qnamemin-test.internet.nl from 185.49.140.61.

27-Apr-2021 20:58:00.329 resolver: debug 5: QNAME minimization - not minimized, qmintype 16 qminname a.b.qnamemin-test.internet.nl
27-Apr-2021 20:58:00.329 database: debug 5: dns_adb_destroyfind on find 0x7ff8aedaef10
27-Apr-2021 20:58:00.329 database: debug 5: dns_adb_destroyfind on find 0x7ff8aeda7110
27-Apr-2021 20:58:00.329 resolver: debug 3: fctx 0x7ff8a0002cb0(a.b.qnamemin-test.internet.nl/TXT): createfind for 127.0.0.1#35679/64023 - success
27-Apr-2021 20:58:00.329 database: debug 5: dns_adb_destroyfind on find 0x7ff8aedaed10
27-Apr-2021 20:58:00.497 resolver: debug 10: received packet from 185.49.140.61#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  38154
;; flags: qr aa; QUESTION: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
;; QUESTION SECTION:
;a.b.qnamemin-test.internet.nl.	IN	TXT

;; ANSWER SECTION:
;a.b.qnamemin-test.internet.nl. 10 IN	TXT	"NO - QNAME minimisation is NOT enabled on your resolver :("

;; AUTHORITY SECTION:
;a.b.qnamemin-test.internet.nl. 10 IN	NS	ns.a.b.qnamemin-test.internet.nl.

;; ADDITIONAL SECTION:
;ns.a.b.qnamemin-test.internet.nl. 10 IN	A	185.49.140.61
;ns.a.b.qnamemin-test.internet.nl. 10 IN	AAAA	2a04:b900::8:0:0:61

It's that last step there that we are wondering about. Our understanding is that bind should have requested the NS of b.qnamemin-test.internet.nl, not the TXT for a.b.qnamemin-test.internet.nl.

This has the result where the qnamemin-test appears to be successful once, and then fails after the first ten seconds. we've waited for an hour to let the internet.nl record expire after that to see if that changed things, but we sill kept asking the wrong server for that TXT record if we are following what we expected qname minimization to do.

Please let us know if we've mis-understood this, or if we can provide anything else to clear this up.

Cheers, Wil