Message "Loop detected resolving..." and different query-behavior after flushing a cache entry

Tue Feb 21 13:24:18 UTC 2023

Tom,

the ADB (Address DataBase) responsible for caching the delegations had been
heavily refactoring in 9.19 branch, I think the best course of action would be to
fill a GitLab issue with the description, so we can follow-up there.

Ondrej
--
Ondřej Surý (He/Him)
ondrej at isc.org

My working hours and your working hours may be different. Please do not feel obligated to reply outside your normal working hours.

> On 21. 2. 2023, at 10:03, Tom <lists at verreckte-cheib.ch> wrote:
> 
> Hi list
> 
> Using BIND-9.19.10:
> 
> An A-query on our resolver for "ns2.comtronic.ch" causes the following info in the named.log, after the first response was answered to the client and cached and then the entry is flushed from cache with "rndc flushname ns2.comtronic.ch":
> 21-Feb-2023 09:23:15.463 resolver: info: loop detected resolving 'ns2.comtronic.ch/A'
> 
> 
> The appropriate tcpdump for BIND-9.19.10 while the loop is detected looks like this (after flushing the cached name with "rndc flushname ns2.comtronic.ch"):
> 
> # Client query
> 09:27:25.957381 IP 10.100.2.62.54792 > 10.100.102.21.53: 4744+ [1au] A? ns2.comtronic.ch. (57)
> 
> # Query from the resolver to the authoritative server for A
> 09:27:25.957984 IP6 2001:db8::affe.20495 > 2a02:1368:1:47::53.53: 50231 [1au] A? ns2.comtronic.ch. (45)
> 
> 
> # Querying TLD nameserver for A and AAAA
> 09:27:25.958177 IP6 2001:db8::affe.13748 > 2001:678:3::1.53: 9026% [1au] AAAA? ns2.comtronic.ch. (45)
> 09:27:25.958283 IP6 2001:db8::affe.2773 > 2001:678:3::1.53: 20217% [1au] A? ns2.comtronic.ch. (45)
> 
> # Response from the authoritative
> 09:27:25.958684 IP6 2a02:1368:1:47::53.53 > 2001:db8::affe.20495: 50231*- 1/0/1 A 195.200.242.162 (61)
> 
> # Response back to the client
> 09:27:25.958915 IP 10.100.102.21.53 > 10.100.2.62.54792: 4744 1/0/1 A 195.200.242.162 (89)
> 
> 
> # Delegations back from the TLD nameserver for the A and AAAA query
> 09:27:25.960140 IP6 2001:678:3::1.53 > 2001:db8::affe.13748: 9026- 0/10/10 (695)
> 09:27:25.960284 IP6 2001:678:3::1.53 > 2001:db8::affe.2773: 20217- 0/10/10 (695)
> 
> 
> # Query against another authoritative for A and AAAA
> 09:27:25.960516 IP6 2001:db8::affe.30306 > 2a02:1368:1:48::53.53: 6112% [1au] AAAA? ns2.comtronic.ch. (45)
> 09:27:25.960543 IP6 2001:db8::affe.5267 > 2a02:1368:1:48::53.53: 8517% [1au] A? ns2.comtronic.ch. (45)
> 
> 
> # Answer back from the authoritative (no AAAA record found for "ns2.comtronic.ch)
> 09:27:25.961284 IP6 2a02:1368:1:48::53.53 > 2001:db8::affe.5267: 8517*- 1/0/1 A 195.200.242.162 (61)
> 09:27:25.961374 IP6 2a02:1368:1:48::53.53 > 2001:db8::affe.30306: 6112*- 0/1/1 (96)
> 
> 
> 
> BIND-9.19.10 behaves differently to BIND-9.18.12 regarding AAAA-Lookups. BIND-9.18.12 doesn't query for AAAA lookup after flushing the name, where BIND-9.19.10 always does with the same configuration..., why?
> See below, here is the appropriate tcpdump with BIND-9.18.12 for a enforced "loop detection resolving" info (after flushing the name with "rndc flushname ns2.comtronic.ch"):
> 
> # 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)
> 
> 
> 
> The info "loop detected resolving" is always reproducable in BIND-9.19.10 after flushing the name "ns2.comtronic.ch", but only sporadic in BIND-9.18.12.
> 
> So my questions are:
> - What does "loop detected resolving 'ns2.comtronic.ch/A' means here?
> - Why is "loop detected resolving 'ns2.comtronic.ch/A'" always reproducable in BIND-9.19.10 and sporadic in BIND-9.18.12?
> - Why does BIND-9.19.10 behaves differently to BIND-9.18.12 regarding AAAA lookups after flushing the name "ns2.comtronic.ch"?
>    - BIND-9.19.10 does A and AAAA lookups after flushing the name "ns2.comtronic.ch", where BIND-9.18.12 only queries for A records
> 
> 
> Many thanks for any hints.
> Best regards,
> Tom
> -- 
> Visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list
> 
> ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information.
> 
> 
> bind-users mailing list
> bind-users at lists.isc.org
> https://lists.isc.org/mailman/listinfo/bind-users