QNAME minimization test fails as non-minimized request is served from cache
Summary
When using default configuration for BIND the QNAME minimization test hosted at internet.nl would fail randomly after four or more iterations. It appears that the fourth request in a row is served the proper minimized request cached previously, but triggers a fetch at the same time which is not minimized. The response to that request is then served to the following fifth request and beyond.
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491 (qnamemintest.internet.nl): query: qnamemintest.internet.nl IN TXT + (127.0.0.1)
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491 (qnamemintest.internet.nl): query (cache) 'qnamemintest.internet.nl/TXT/IN' approved
17-Nov-2021 06:17:13.568 fetch: a.b.qnamemin-test.internet.nl/TXT
17-Nov-2021 06:17:13.568 log_ns_ttl: fctx 0x7fef80044e60: fctx_create: a.b.qnamemin-test.internet.nl (in 'internet.nl'?): 1 3587
17-Nov-2021 06:17:13.568 QNAME minimization - not minimized, qmintype 16 qminname a.b.qnamemin-test.internet.nl
BIND version used
BIND 9.16.22-Ubuntu (Extended Support Version) id:59bfaba
Steps to reproduce
We ran the following bash commands and this behaviour would occur sometimes after four of five iterations, other times after a dozen or more. We echo'ed the date
command into the log as well to line up events.
for i in {1..30};
do date +"%T.%6N";
echo "Test Number " $i;
echo "========== Before test" $i >> /var/log/named/default.log;
kdig +nodnssec +short @127.0.0.1 qnamemintest.internet.nl TXT;
date +"%T.%6N";
echo "======== done test" $i >> /var/log/named/default.log;
echo "Test Number " $i "done, sleeping.";
sleep 3;
done
What is the current bug behavior?
Here the test fails on the fifth iteration
06:16:57.072993
Test Number 1
;; WARNING: response timeout for 127.0.0.1@53(UDP)
a.b.qnamemin-test.internet.nl.
"HOORAY - QNAME minimisation is enabled on your resolver :)!"
06:17:04.540956
Test Number 1 done, sleeping.
06:17:07.545660
Test Number 2
a.b.qnamemin-test.internet.nl.
"HOORAY - QNAME minimisation is enabled on your resolver :)!"
06:17:07.551628
Test Number 2 done, sleeping.
06:17:10.556281
Test Number 3
a.b.qnamemin-test.internet.nl.
"HOORAY - QNAME minimisation is enabled on your resolver :)!"
06:17:10.562749
Test Number 3 done, sleeping.
06:17:13.567638
Test Number 4
a.b.qnamemin-test.internet.nl.
"HOORAY - QNAME minimisation is enabled on your resolver :)!"
06:17:13.574423
Test Number 4 done, sleeping.
06:17:16.578864
Test Number 5
a.b.qnamemin-test.internet.nl.
"NO - QNAME minimisation is NOT enabled on your resolver :("
06:17:16.584539
Test Number 5 done, sleeping.
06:17:19.588370
Test Number 6
a.b.qnamemin-test.internet.nl.
"NO - QNAME minimisation is NOT enabled on your resolver :("
06:17:19.594741
Test Number 6 done, sleeping.
Part of the internet.nl test is to serve a different TXT record based on the delegation path for their records. If you do not follow QNAME minimization to spec, you will miss a delegation and be served a different record than if you had walked the whole way down from the top. In this case, we are served the failure message.
In the debug below, we see that the fourth test is served from cache while a new fetch of the TXT is started and not minimized. That response arrives after the fourth request has been served and before the fifth. The fifth is then sent the non-minimized response.
========== Before test 4
17-Nov-2021 06:17:13.568 clientmgr @0x7fef8ee53190 attach: 4
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 (no-peer): allocate new client
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491: UDP request
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491: using view '_default'
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491: request is not signed
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491: recursion available
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491 (qnamemintest.internet.nl): query: qnamemintest.internet.nl IN TXT + (127.0.0.1)
17-Nov-2021 06:17:13.568 client @0x7fef808ae838 127.0.0.1#35491 (qnamemintest.internet.nl): query (cache) 'qnamemintest.internet.nl/TXT/IN' approved
17-Nov-2021 06:17:13.568 fetch: a.b.qnamemin-test.internet.nl/TXT
17-Nov-2021 06:17:13.568 log_ns_ttl: fctx 0x7fef80044e60: fctx_create: a.b.qnamemin-test.internet.nl (in 'internet.nl'?): 1 3587
17-Nov-2021 06:17:13.568 QNAME minimization - not minimized, qmintype 16 qminname a.b.qnamemin-test.internet.nl
17-Nov-2021 06:17:13.568 expiring v4 for name 0x7fef8432c600
17-Nov-2021 06:17:13.568 expire_v4 set to MIN(2147483647,1637129843) import_rdataset
17-Nov-2021 06:17:13.568 dns_adb_createfind: found A for name ns1.sidnlabs.nl (0x7fef8432c600) in db
17-Nov-2021 06:17:13.568 fctx 0x7fef80044e60(a.b.qnamemin-test.internet.nl/TXT): createfind for 127.0.0.1#35491/54667 - success
17-Nov-2021 06:17:13.568 expiring v4 for name 0x7fef8432c4d0
17-Nov-2021 06:17:13.568 expire_v4 set to MIN(2147483647,1637129843) import_rdataset
17-Nov-2021 06:17:13.568 dns_adb_createfind: found A for name ns3.sidn.nl (0x7fef8432c4d0) in db
17-Nov-2021 06:17:13.568 fctx 0x7fef80044e60(a.b.qnamemin-test.internet.nl/TXT): createfind for 127.0.0.1#35491/54667 - success
17-Nov-2021 06:17:13.568 socket 0x7fef8419c178: socket_recv: event 0x7fef8419f160 -> task 0x7fef84914550
17-Nov-2021 06:17:13.568 sending packet to 94.198.159.8#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 15820
;; flags:; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: 6e57d9bce860fbf50100000061949e5c594abc51bbb6293a
;; QUESTION SECTION:
;a.b.qnamemin-test.internet.nl. IN TXT
======== done test 4
17-Nov-2021 06:17:13.844 socket 0x7fef8419c178: socket_recv: event 0x7fef8419f010 -> task 0x7fef84914550
17-Nov-2021 06:17:13.844 received packet from 94.198.159.8#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 15820
;; flags: qr; QUESTION: 1, ANSWER: 0, AUTHORITY: 3, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: 6e57d9bce860fbf50100000061949e69a15a47ca6fecf4ce
;; QUESTION SECTION:
;a.b.qnamemin-test.internet.nl. IN TXT
;; AUTHORITY SECTION:
;qnamemin-test.internet.nl. 10 IN NS ns.qnamemin-test.internet.nl.
;37EVSMIUKP9K7OAANU0THSBL3AFJAJJI.internet.nl. 300 IN NSEC3 1 0 0 - (
; 3UK0OFP95GPMB6AJ2O611UGNO7EJ4O6U
; NS )
;37EVSMIUKP9K7OAANU0THSBL3AFJAJJI.internet.nl. 300 IN RRSIG NSEC3 13 3 300 (
; 20211212072148 20211112065813 16313 internet.nl.
; E/vfuxroRZjeupIxjp+s3aQpKPb0
; fYR3UjTMs3yoHhF66kz/wvPyuwvY
; 9vlHJ1UmifUBfmyAtZj560mQ0loV
; MQ== )
;; 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
17-Nov-2021 06:17:13.844 log_ns_ttl: fctx 0x7fef80044e60: rctx_answer_none: a.b.qnamemin-test.internet.nl (in 'internet.nl'?): 1 3587
17-Nov-2021 06:17:13.844 QNAME minimization - not minimized, qmintype 16 qminname a.b.qnamemin-test.internet.nl
17-Nov-2021 06:17:13.844 log_ns_ttl: fctx 0x7fef80044e60: DELEGATION: a.b.qnamemin-test.internet.nl (in 'qnamemin-test.internet.nl'?): 0 3587
17-Nov-2021 06:17:13.844 dns_adb_destroyfind on find 0x7fef84329d10
17-Nov-2021 06:17:13.844 dns_adb_destroyfind on find 0x7fef84327e10
17-Nov-2021 06:17:13.844 expiring v4 for name 0x7fef8432c3a0
17-Nov-2021 06:17:13.844 expire_v4 set to MIN(2147483647,1637129843) import_rdataset
17-Nov-2021 06:17:13.844 dns_adb_createfind: found A for name ns.qnamemin-test.internet.nl (0x7fef8432c3a0) in db
17-Nov-2021 06:17:13.844 fctx 0x7fef80044e60(a.b.qnamemin-test.internet.nl/TXT): createfind for 127.0.0.1#35491/54667 - success
17-Nov-2021 06:17:13.844 socket 0x7fef8419c010: socket_recv: event 0x7fef841a0550 -> task 0x7fef849186d0
17-Nov-2021 06:17:13.844 sending packet to 185.49.140.61#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 7077
;; flags:; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: e77abc1b4903389a
;; QUESTION SECTION:
;a.b.qnamemin-test.internet.nl. IN TXT
17-Nov-2021 06:17:14.236 socket 0x7fef8419c010: socket_recv: event 0x7fef841a0400 -> task 0x7fef849186d0
17-Nov-2021 06:17:14.236 received packet from 185.49.140.61#53
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 7077
;; 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
17-Nov-2021 06:17:14.236 log_ns_ttl: fctx 0x7fef80044e60: rctx_answer: a.b.qnamemin-test.internet.nl (in 'qnamemin-test.internet.nl'?): 1 10
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: starting
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: attempting insecurity proof
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: checking existence of DS at 'nl'
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: checking existence of DS at 'internet.nl'
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: checking existence of DS at 'qnamemin-test.internet.nl'
17-Nov-2021 06:17:14.236 validating a.b.qnamemin-test.internet.nl/TXT: marking as answer (proveunsecure (4))
17-Nov-2021 06:17:14.236 validator @0x7fef80047440: dns_validator_destroy
17-Nov-2021 06:17:14.236 delete_node(): 0x7fef8482b940 ns.a.b.qnamemin-test.internet.nl (bucket 13)
17-Nov-2021 06:17:14.236 client @0x7fef808ae838 127.0.0.1#35491 (qnamemintest.internet.nl): reset client
17-Nov-2021 06:17:14.236 dns_adb_destroyfind on find 0x7fef84327e10
========== Before test 5
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992: UDP request
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992: using view '_default'
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992: request is not signed
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992: recursion available
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992 (qnamemintest.internet.nl): query: qnamemintest.internet.nl IN TXT + (127.0.0.1)
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992 (qnamemintest.internet.nl): query (cache) 'qnamemintest.internet.nl/TXT/IN' approved
17-Nov-2021 06:17:16.580 client @0x7fef78053e18 127.0.0.1#45992 (qnamemintest.internet.nl): reset client
======== done test 5
What is the expected correct behavior?
We believe that served from cache or not, all requests should be minimized and this test should pass every time.
Relevant logs and/or screenshots
We have qname-minimization strict;
set in named.conf.options
.
Beyond that and some logging changes, we are using the default configuration.
Possible fixes
Wish I was that skilled to help out. I have previously opened #2665 (closed) which was similar, so some of the work there might be relevant.