nslookup reports timeout if input lookup is delayed

Summary

BIND version used

BIND 9.18.14 (Extended Support Version) <id:>
running on Linux x86_64 6.2.12-300.fc38.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Apr 20 23:05:25 UTC 2023
built by make with  '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--runstatedir=/run' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--localstatedir=/var' '--with-pic' '--disable-static' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-libidn2' '--with-maxminddb' '--with-gssapi=yes' '--with-lmdb=yes' '--with-json-c' '--enable-dnstap' '--with-cmocka' '--enable-fixed-rrset' '--enable-full-report' 'CPPFLAGS= -DOPENSSL_API_COMPAT=10100' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CC=gcc' 'CFLAGS=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-U_FORTIFY_SOURCE,-D_FORTIFY_SOURCE=3 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer  -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-U_FORTIFY_SOURCE,-D_FORTIFY_SOURCE=3 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64  -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed  -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -Wl,--build-id=sha1 -specs=/usr/lib/rpm/redhat/redhat-package-notes ' 'LT_SYS_LIBRARY_PATH=/usr/lib64:' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig'
compiled by GCC 13.0.1 20230401 (Red Hat 13.0.1-0)
compiled with OpenSSL version: OpenSSL 3.0.8 7 Feb 2023
linked to OpenSSL version: OpenSSL 3.0.8 7 Feb 2023
compiled with libuv version: 1.44.2
linked to libuv version: 1.44.2
compiled with libnghttp2 version: 1.52.0
linked to libnghttp2 version: 1.52.0
compiled with libxml2 version: 2.10.4
linked to libxml2 version: 21004
compiled with json-c version: 0.16
linked to json-c version: 0.16
compiled with zlib version: 1.2.13
linked to zlib version: 1.2.13
linked to maxminddb version: 1.7.1
compiled with protobuf-c version: 1.4.1
linked to protobuf-c version: 1.4.1
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): yes

default paths:
  named configuration:  /etc/named.conf
  rndc configuration:   /etc/rndc.conf
  DNSSEC root key:      /etc/bind.keys
  nsupdate session key: /var/run/named/session.key
  named PID file:       /var/run/named/named.pid
  named lock file:      /var/run/named/named.lock
  geoip-directory:      /usr/share/GeoIP

Steps to reproduce

(sleep 6 && echo localhost.) | nslookup

What is the current bug behavior?

Starts with ;; communications error to 127.0.0.53#53: timed out

What is the expected correct behavior?

Just like in development releases, no timeout is reported, because no timeout did occur.

Relevant configuration files

no configuration, just /etc/resolv.conf.

Relevant logs and/or screenshots

reported on https://bugzilla.redhat.com/show_bug.cgi?id=2192225

$ (sleep 6 && echo localhost.) | nslookup
;; communications error to 127.0.0.53#53: timed out
Server:		127.0.0.53
Address:	127.0.0.53#53

Name:	localhost
Address: 127.0.0.1
Name:	localhost
Address: ::1

$ (sleep 6 && echo "set d2" && echo localhost.) | nslookup 2>&1 | tee out
$ cat out 
addlookup()
make_empty_lookup()
make_empty_lookup() = 0x7f7abb5b2000->references = 1
looking up localhost.
start_lookup()
setup_lookup(0x7f7abb5b2000)
resetting lookup counter.
cloning server list
clone_server_list()
make_server(127.0.0.53)
using root origin
recursive query
add_question()
starting to render the message
done rendering
create query 0x7f7abb5e3000 linked to lookup 0x7f7abb5b2000
../../../bin/dig/dighost.c:2177:lookup_attach(0x7f7abb5b2000) = 2
../../../bin/dig/dighost.c:2690:new_query(0x7f7abb5e3000) = 1
do_lookup()
start_udp(0x7f7abb5e3000)
../../../bin/dig/dighost.c:3301:query_attach(0x7f7abb5e3000) = 2
working on lookup 0x7f7abb5b2000, query 0x7f7abb5e3000
../../../bin/dig/dighost.c:3346:query_attach(0x7f7abb5e3000) = 3
udp_ready()
udp_ready(0x7f7aba5a1000, success, 0x7f7abb5e3000)
lock_lookup ../../../bin/dig/dighost.c:3188
success
../../../bin/dig/dighost.c:3189:lookup_attach(0x7f7abb5b2000) = 3
../../../bin/dig/dighost.c:3261:query_attach(0x7f7abb5e3000) = 4
recving with lookup=0x7f7abb5b2000, query=0x7f7abb5e3000, handle=0x7f7aba5a1000
recvcount=1
have local timeout of 5000
../../../bin/dig/dighost.c:3135:query_attach(0x7f7abb5e3000) = 5
sending a request
sendcount=1
../../../bin/dig/dighost.c:1761:query_detach(0x7f7abb5e3000) = 4
../../../bin/dig/dighost.c:3281:query_detach(0x7f7abb5e3000) = 3
../../../bin/dig/dighost.c:3282:lookup_detach(0x7f7abb5b2000) = 2
unlock_lookup ../../../bin/dig/dighost.c:3283
send_done(0x7f7aba5a1000, success, 0x7f7abb5e3000)
sendcount=0
lock_lookup ../../../bin/dig/dighost.c:2765
success
../../../bin/dig/dighost.c:2769:lookup_attach(0x7f7abb5b2000) = 3
../../../bin/dig/dighost.c:2787:query_detach(0x7f7abb5e3000) = 2
../../../bin/dig/dighost.c:2788:lookup_detach(0x7f7abb5b2000) = 2
check_if_done()
list empty
unlock_lookup ../../../bin/dig/dighost.c:2792
recv_done(0x7f7aba5a1000, timed out, 0x7f7abaffe0c0, 0x7f7abb5e3000)
lock_lookup ../../../bin/dig/dighost.c:3955
success
recvcount=0
../../../bin/dig/dighost.c:3960:lookup_attach(0x7f7abb5b2000) = 3
;; communications error to 127.0.0.53#53: timed out
create query 0x7f7abb5e31c0 linked to lookup 0x7f7abb5b2000
../../../bin/dig/dighost.c:2177:lookup_attach(0x7f7abb5b2000) = 4
../../../bin/dig/dighost.c:4048:new_query(0x7f7abb5e31c0) = 1
making new UDP request, 2 tries left
start_udp(0x7f7abb5e31c0)
../../../bin/dig/dighost.c:3301:query_attach(0x7f7abb5e31c0) = 2
working on lookup 0x7f7abb5b2000, query 0x7f7abb5e31c0
../../../bin/dig/dighost.c:3346:query_attach(0x7f7abb5e31c0) = 3
check_if_queries_done(0x7f7abb5b2000)
there is a pending query 0x7f7abb5e31c0
../../../bin/dig/dighost.c:4554:query_detach(0x7f7abb5e3000) = 1
../../../bin/dig/dighost.c:4562:lookup_detach(0x7f7abb5b2000) = 3
unlock_lookup ../../../bin/dig/dighost.c:4566
udp_ready()
udp_ready(0x7f7aba5a1300, success, 0x7f7abb5e31c0)
lock_lookup ../../../bin/dig/dighost.c:3188
success
../../../bin/dig/dighost.c:3189:lookup_attach(0x7f7abb5b2000) = 4
../../../bin/dig/dighost.c:3261:query_attach(0x7f7abb5e31c0) = 4
recving with lookup=0x7f7abb5b2000, query=0x7f7abb5e31c0, handle=0x7f7aba5a1300
recvcount=1
have local timeout of 5000
../../../bin/dig/dighost.c:3135:query_attach(0x7f7abb5e31c0) = 5
sending a request
sendcount=1
../../../bin/dig/dighost.c:1761:query_detach(0x7f7abb5e31c0) = 4
../../../bin/dig/dighost.c:3281:query_detach(0x7f7abb5e31c0) = 3
../../../bin/dig/dighost.c:3282:lookup_detach(0x7f7abb5b2000) = 3
unlock_lookup ../../../bin/dig/dighost.c:3283
send_done(0x7f7aba5a1300, success, 0x7f7abb5e31c0)
sendcount=0
lock_lookup ../../../bin/dig/dighost.c:2765
success
../../../bin/dig/dighost.c:2769:lookup_attach(0x7f7abb5b2000) = 4
../../../bin/dig/dighost.c:2787:query_detach(0x7f7abb5e31c0) = 2
../../../bin/dig/dighost.c:2788:lookup_detach(0x7f7abb5b2000) = 3
check_if_done()
list empty
unlock_lookup ../../../bin/dig/dighost.c:2792
recv_done(0x7f7aba5a1300, success, 0x7f7abaffad40, 0x7f7abb5e31c0)
lock_lookup ../../../bin/dig/dighost.c:3955
success
recvcount=0
../../../bin/dig/dighost.c:3960:lookup_attach(0x7f7abb5b2000) = 4
before parse starts
after parse
printmessage()
Server:		127.0.0.53
Address:	127.0.0.53#53

clone_lookup()
make_empty_lookup()
make_empty_lookup() = 0x7f7abb5b3800->references = 1
printsection()
Name:	localhost
Address: 127.0.0.1
still pending.
../../../bin/dig/dighost.c:4554:query_detach(0x7f7abb5e31c0) = 1
../../../bin/dig/dighost.c:4556:_cancel_lookup()
canceling pending query 0x7f7abb5e3000, belonging to 0x7f7abb5b2000
../../../bin/dig/dighost.c:2817:query_detach(0x7f7abb5e3000) = 0
../../../bin/dig/dighost.c:2817:destroy_query(0x7f7abb5e3000) = 0
../../../bin/dig/dighost.c:1719:lookup_detach(0x7f7abb5b2000) = 3
canceling pending query 0x7f7abb5e31c0, belonging to 0x7f7abb5b2000
../../../bin/dig/dighost.c:2817:query_detach(0x7f7abb5e31c0) = 0
../../../bin/dig/dighost.c:2817:destroy_query(0x7f7abb5e31c0) = 0
../../../bin/dig/dighost.c:1719:lookup_detach(0x7f7abb5b2000) = 2
check_if_done()
list full
pending lookup 0x7f7abb5b3800
../../../bin/dig/dighost.c:4562:lookup_detach(0x7f7abb5b2000) = 1
clear_current_lookup()
lookup cleared
../../../bin/dig/dighost.c:1852:lookup_detach(0x7f7abb5b2000) = 0
destroy_lookup
freeing server 0x7f7abb595400 belonging to 0x7f7abb5b2000
start_lookup()
setup_lookup(0x7f7abb5b3800)
cloning server list
clone_server_list()
make_server(127.0.0.53)
using root origin
recursive query
add_question()
starting to render the message
done rendering
create query 0x7f7abb5e31c0 linked to lookup 0x7f7abb5b3800
../../../bin/dig/dighost.c:2177:lookup_attach(0x7f7abb5b3800) = 2
../../../bin/dig/dighost.c:2690:new_query(0x7f7abb5e31c0) = 1
do_lookup()
start_udp(0x7f7abb5e31c0)
../../../bin/dig/dighost.c:3301:query_attach(0x7f7abb5e31c0) = 2
working on lookup 0x7f7abb5b3800, query 0x7f7abb5e31c0
../../../bin/dig/dighost.c:3346:query_attach(0x7f7abb5e31c0) = 3
unlock_lookup ../../../bin/dig/dighost.c:4566
udp_ready()
udp_ready(0x7f7aba5a1180, success, 0x7f7abb5e31c0)
lock_lookup ../../../bin/dig/dighost.c:3188
success
../../../bin/dig/dighost.c:3189:lookup_attach(0x7f7abb5b3800) = 3
../../../bin/dig/dighost.c:3261:query_attach(0x7f7abb5e31c0) = 4
recving with lookup=0x7f7abb5b3800, query=0x7f7abb5e31c0, handle=0x7f7aba5a1180
recvcount=1
have local timeout of 5000
../../../bin/dig/dighost.c:3135:query_attach(0x7f7abb5e31c0) = 5
sending a request
sendcount=1
../../../bin/dig/dighost.c:1761:query_detach(0x7f7abb5e31c0) = 4
../../../bin/dig/dighost.c:3281:query_detach(0x7f7abb5e31c0) = 3
../../../bin/dig/dighost.c:3282:lookup_detach(0x7f7abb5b3800) = 2
unlock_lookup ../../../bin/dig/dighost.c:3283
send_done(0x7f7aba5a1180, success, 0x7f7abb5e31c0)
sendcount=0
lock_lookup ../../../bin/dig/dighost.c:2765
success
../../../bin/dig/dighost.c:2769:lookup_attach(0x7f7abb5b3800) = 3
../../../bin/dig/dighost.c:2787:query_detach(0x7f7abb5e31c0) = 2
../../../bin/dig/dighost.c:2788:lookup_detach(0x7f7abb5b3800) = 2
check_if_done()
list empty
unlock_lookup ../../../bin/dig/dighost.c:2792
recv_done(0x7f7aba5a1180, success, 0x7f7abaffad40, 0x7f7abb5e31c0)
lock_lookup ../../../bin/dig/dighost.c:3955
success
recvcount=0
../../../bin/dig/dighost.c:3960:lookup_attach(0x7f7abb5b3800) = 3
before parse starts
after parse
printmessage()
printsection()
Name:	localhost
Address: ::1
still pending.
../../../bin/dig/dighost.c:4554:query_detach(0x7f7abb5e31c0) = 1
../../../bin/dig/dighost.c:4556:_cancel_lookup()
canceling pending query 0x7f7abb5e31c0, belonging to 0x7f7abb5b3800
../../../bin/dig/dighost.c:2817:query_detach(0x7f7abb5e31c0) = 0
../../../bin/dig/dighost.c:2817:destroy_query(0x7f7abb5e31c0) = 0
../../../bin/dig/dighost.c:1719:lookup_detach(0x7f7abb5b3800) = 2
check_if_done()
list empty
../../../bin/dig/dighost.c:4562:lookup_detach(0x7f7abb5b3800) = 1
clear_current_lookup()
lookup cleared
../../../bin/dig/dighost.c:1852:lookup_detach(0x7f7abb5b3800) = 0
destroy_lookup
freeing server 0x7f7abb595400 belonging to 0x7f7abb5b3800
start_lookup()
check_if_done()
list empty
shutting down
dighost_shutdown()
unlock_lookup ../../../bin/dig/dighost.c:4566

done, and starting to shut down
cancel_all()
lock_lookup ../../../bin/dig/dighost.c:4675
success
unlock_lookup ../../../bin/dig/dighost.c:4709
destroy_libs()
freeing task
lock_lookup ../../../bin/dig/dighost.c:4748
success
flush_server_list()
destroy DST lib
unlock_lookup ../../../bin/dig/dighost.c:4769
Removing log context
Destroy memory

Possible fixes

I were unable to find exact spot where this happens. It recv_done already receives eresult==timed out, so I suspect libuv wrappers might be responsible. In master branch this seems to be fixed, happens on v9_18 only.

Edited May 03, 2023 by Petr Menšík

To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information