"Loop detected resolving..." and different query-behavior after flushing a cache entry between BIND-9.19.10 and BIND-9.18.12
Summary
Regarding https://www.mail-archive.com/bind-users@lists.isc.org/msg33119.html, I fill this GL issue.
BIND-9.19.10 behaves differently to BIND-9.18.12 regarding AAAA-Lookups, when an entry (for example A record for "ns2.comtronic.ch") was cached and then succesfully flushed with rndc flushname ns2.comtronic.ch
.
BIND-9.19.10 then always...
- does A and AAAA lookups for the requested query (
dig @resolver ns2.comtronic.ch
) - shows an INFO
21-Feb-2023 09:23:15.463 resolver: info: loop detected resolving 'ns2.comtronic.ch/A'
... where BIND-9.18.12 only sporadic shows the loop detected info and doesn't do AAAA lookups.
BIND version used
9.19.10
$ named -V
BIND 9.19.10 (Development Release) <id:789be8e>
running on Linux x86_64 4.18.0-305.10.2.el8_4.x86_64 #1 SMP Tue Jul 20 20:34:55 UTC 2021
built by make with '--prefix=/usr/local/bind-9.19.10' '--sysconfdir=/opt/chroot/bind/etc/named/' '--mandir=/usr/local/share/man' '--localstatedir=/opt/chroot/bind/var' '--enable-largefile' '--enable-full-report' '--without-gssapi' '--with-json-c' '--enable-singletrace' '--enable-dnstap' '--with-libxml2' 'PKG_CONFIG_PATH=/usr/local/fstrm/lib/pkgconfig/:/usr/local/h2o/lib64/pkgconfig'
compiled by GCC 8.4.1 20200928 (Red Hat 8.4.1-1)
compiled with OpenSSL version: OpenSSL 1.1.1g FIPS 21 Apr 2020
linked to OpenSSL version: OpenSSL 1.1.1g FIPS 21 Apr 2020
compiled with libuv version: 1.41.1
linked to libuv version: 1.41.1
compiled with libnghttp2 version: 1.33.0
linked to libnghttp2 version: 1.33.0
compiled with libxml2 version: 2.9.7
linked to libxml2 version: 20907
compiled with json-c version: 0.13.1
linked to json-c version: 0.13.1
compiled with zlib version: 1.2.11
linked to zlib version: 1.2.11
compiled with protobuf-c version: 1.3.0
linked to protobuf-c version: 1.3.0
threads support is enabled
DNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
DS algorithms: SHA-1 SHA-256 SHA-384
HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
TKEY mode 2 support (Diffie-Hellman): yes
TKEY mode 3 support (GSS-API): no
default paths:
named configuration: /opt/chroot/bind/etc/named/named.conf
rndc configuration: /opt/chroot/bind/etc/named/rndc.conf
DNSSEC root key: /opt/chroot/bind/etc/named/bind.keys
nsupdate session key: /opt/chroot/bind/var/run/named/session.key
named PID file: /opt/chroot/bind/var/run/named/named.pid
named lock file: /opt/chroot/bind/var/run/named/named.lock
9.18.12
$ named -V
BIND 9.18.12 (Extended Support Version) <id:99783f9>
running on Linux x86_64 4.18.0-305.10.2.el8_4.x86_64 #1 SMP Tue Jul 20 20:34:55 UTC 2021
built by make with '--prefix=/usr/local/bind-9.18.12' '--sysconfdir=/opt/chroot/bind/etc/named/' '--mandir=/usr/local/share/man' '--localstatedir=/opt/chroot/bind/var' '--enable-largefile' '--enable-full-report' '--without-gssapi' '--with-json-c' '--enable-singletrace' '--enable-dnstap' '--with-libxml2' 'PKG_CONFIG_PATH=/usr/local/fstrm/lib/pkgconfig/:/usr/local/h2o/lib64/pkgconfig'
compiled by GCC 8.4.1 20200928 (Red Hat 8.4.1-1)
compiled with OpenSSL version: OpenSSL 1.1.1g FIPS 21 Apr 2020
linked to OpenSSL version: OpenSSL 1.1.1g FIPS 21 Apr 2020
compiled with libuv version: 1.41.1
linked to libuv version: 1.41.1
compiled with libnghttp2 version: 1.33.0
linked to libnghttp2 version: 1.33.0
compiled with libxml2 version: 2.9.7
linked to libxml2 version: 20907
compiled with json-c version: 0.13.1
linked to json-c version: 0.13.1
compiled with zlib version: 1.2.11
linked to zlib version: 1.2.11
compiled with protobuf-c version: 1.3.0
linked to protobuf-c version: 1.3.0
threads support is enabled
DNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
DS algorithms: SHA-1 SHA-256 SHA-384
HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
TKEY mode 2 support (Diffie-Hellman): yes
TKEY mode 3 support (GSS-API): no
default paths:
named configuration: /opt/chroot/bind/etc/named/named.conf
rndc configuration: /opt/chroot/bind/etc/named/rndc.conf
DNSSEC root key: /opt/chroot/bind/etc/named/bind.keys
nsupdate session key: /opt/chroot/bind/var/run/named/session.key
named PID file: /opt/chroot/bind/var/run/named/named.pid
named lock file: /opt/chroot/bind/var/run/named/named.lock
Steps to reproduce
# Start named on the resolver
$ systemctl start named
# Query the record, which causes the behavior
$ dig @resolver ns2.comtronic.ch
; <<>> DiG 9.19.10 <<>> @resolver ns2.comtronic.ch
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 22395
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
; COOKIE: 6a9803403ae47edc0100000063f4e59976baec2fb3207c4a (good)
;; QUESTION SECTION:
;ns2.comtronic.ch. IN A
;; ANSWER SECTION:
ns2.comtronic.ch. 60 IN A 195.200.242.162
;; Query time: 12 msec
;; SERVER: 10.100.102.21#53(resolver) (UDP)
;; WHEN: Tue Feb 21 16:39:05 CET 2023
;; MSG SIZE rcvd: 89
# Run "rndc flushname ns2.comtronic.ch"
$ rndc flushname ns2.comtronic.ch
# Query the resolver with the same query again
$ dig @resolver ns2.comtronic.ch
; <<>> DiG 9.19.10 <<>> @resolver ns2.comtronic.ch
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 43078
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
; COOKIE: 70097c934a18c03c0100000063f4e6a0cc14b1551adc474c (good)
;; QUESTION SECTION:
;ns2.comtronic.ch. IN A
;; ANSWER SECTION:
ns2.comtronic.ch. 60 IN A 195.200.242.162
;; Query time: 8 msec
;; SERVER: 10.100.102.21#53(resolver) (UDP)
;; WHEN: Tue Feb 21 16:43:28 CET 2023
;; MSG SIZE rcvd: 89
# On the resolver check the named.log for "loop detected"
21-Feb-2023 16:43:28.238 resolver: info: loop detected resolving 'ns2.comtronic.ch/A'
# On the resolver sniff dns traffic, which always shows A and AAAA lookups
16:43:28.239336 IP 10.100.2.62.43415 > 10.100.102.21.53: 43078+ [1au] A? ns2.comtronic.ch. (57)
16:43:28.240559 IP6 2001:db8::affe.44411 > 2603:1020:a01:2::34.53: 11540 [1au] A? ns2.comtronic.ch. (45)
16:43:28.240885 IP6 2001:db8::affe.33227 > 2001:67c:1010:2::53.53: 46123% [1au] AAAA? ns2.comtronic.ch. (45)
16:43:28.240984 IP6 2001:db8::affe.29014 > 2001:67c:1010:2::53.53: 50359% [1au] A? ns2.comtronic.ch. (45)
16:43:28.243680 IP6 2603:1020:a01:2::34.53 > 2001:db8::affe.44411: 11540*- 1/0/1 A 195.200.242.162 (61)
16:43:28.243951 IP 10.100.102.21.53 > 10.100.2.62.43415: 43078 1/0/1 A 195.200.242.162 (89)
16:43:28.246959 IP6 2001:67c:1010:2::53.53 > 2001:db8::affe.33227: 46123- 0/10/10 (695)
16:43:28.247176 IP6 2001:67c:1010:2::53.53 > 2001:db8::affe.29014: 50359- 0/10/10 (695)
16:43:28.247420 IP6 2001:db8::affe.36611 > 2a02:1368:1:47::53.53: 1441% [1au] AAAA? ns2.comtronic.ch. (45)
16:43:28.247515 IP6 2001:db8::affe.6551 > 2a02:1368:1:47::53.53: 45763% [1au] A? ns2.comtronic.ch. (45)
16:43:28.248042 IP6 2a02:1368:1:47::53.53 > 2001:db8::affe.36611: 1441*- 0/1/1 (96)
16:43:28.248080 IP6 2a02:1368:1:47::53.53 > 2001:db8::affe.6551: 45763*- 1/0/1 A 195.200.242.162 (61)
What is the current bug behavior?
Regarding https://www.mail-archive.com/bind-users@lists.isc.org/msg33119.html it's not clear,
- what "loop detected resolving 'ns2.comtronic.ch/A' means here?
- why "loop detected resolving 'ns2.comtronic.ch/A'" always is reproducable in BIND-9.19.10 and sporadic in BIND-9.18.12?
- why BIND-9.19.10 behaves differently to BIND-9.18.12 regarding AAAA lookups after flushing the name "ns2.comtronic.ch"?
A tcpdump
from BIND-9.18.12 shows the following traffic (excerpt from my mailing-list- question):
# Query from the client
09:36:34.242064 IP 10.100.2.62.59765 > 10.100.102.21.53: 58600+ [1au] A? ns2.comtronic.ch. (57)
# Query from the resolver to the authoritative
09:36:34.242787 IP6 2001:db8::affe.4717 > 2a02:1368:1:48::53.53: 26321 [1au] A? ns2.comtronic.ch. (45)
# Query from the resolver to the TLD server
09:36:34.242880 IP6 2001:db8::affe.25272 > 2001:620:0:ff::56.53: 50695% [1au] A? ns2.comtronic.ch. (45)
# Response back from the authoritative server
09:36:34.243673 IP6 2a02:1368:1:48::53.53 > 2001:db8::affe.4717: 26321*- 1/0/1 A 195.200.242.162 (61)
# Response back to the client
09:36:34.243841 IP 10.100.102.21.53 > 10.100.2.62.59765: 58600 1/0/1 A 195.200.242.162 (89)
# Delegation answer from the TLD server
09:36:34.244556 IP6 2001:620:0:ff::56.53 > 2001:db8::affe.25272: 50695- 0/10/10 (695)
# A 2nd query to the same authoritative
09:36:34.244750 IP6 2001:db8::affe.18083 > 2a02:1368:1:48::53.53: 21395% [1au] A? ns2.comtronic.ch. (45)
# 2nd response back from the authoritative server
09:36:34.245246 IP6 2a02:1368:1:48::53.53 > 2001:db8::affe.18083: 21395*- 1/0/1 A 195.200.242.162 (61)
What is the expected correct behavior?
I'm not sure, which behavior is the correct one, 9.19.10 or 9.18.12.
Relevant configuration files
--
Relevant logs and/or screenshots
--
Possible fixes
--