nslookup timeout is ignored after several requests
Summary
nslookup doesn't properly implement the timeout on lookup sometimes.
BIND version used
BIND 9.18.16-1~deb12u1-Debian (Extended Support Version) <id:>
running on Linux x86_64 6.1.0-rc7-pstate #3 SMP PREEMPT_DYNAMIC Mon Dec 5 22:02:30 AEDT 2022
built by make with '--build=x86_64-linux-gnu' '--prefix=/usr' '--includedir=${prefix}/include' '--mandir=${prefix}/share/man' '--infodir=${prefix}/share/info' '--sysconfdir=/etc' '--localstatedir=/var' '--disable-option-checking' '--disable-silent-rules' '--libdir=${prefix}/lib/x86_64-linux-gnu' '--runstatedir=/run' '--disable-maintainer-mode' '--disable-dependency-tracking' '--libdir=/usr/lib/x86_64-linux-gnu' '--sysconfdir=/etc/bind' '--with-python=python3' '--localstatedir=/' '--enable-threads' '--enable-largefile' '--with-libtool' '--enable-shared' '--disable-static' '--with-gost=no' '--with-openssl=/usr' '--with-gssapi=yes' '--with-libidn2' '--with-json-c' '--with-lmdb=/usr' '--with-gnu-ld' '--with-maxminddb' '--with-atf=no' '--enable-ipv6' '--enable-rrl' '--enable-filter-aaaa' '--disable-native-pkcs11' '--enable-dnstap' 'build_alias=x86_64-linux-gnu' 'CFLAGS=-g -O2 -ffile-prefix-map=/build/bind9-yTvTm0/bind9-9.18.16=. -fstack-protector-strong -Wformat -Werror=format-security -fno-strict-aliasing -fno-delete-null-pointer-checks -DNO_VERSION_DATE -DDIG_SIGCHASE' 'LDFLAGS=-Wl,-z,relro -Wl,-z,now' 'CPPFLAGS=-Wdate-time -D_FORTIFY_SOURCE=2'
compiled by GCC 12.2.0
compiled with OpenSSL version: OpenSSL 3.0.9 30 May 2023
linked to OpenSSL version: OpenSSL 3.0.9 30 May 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.9.14
linked to libxml2 version: 20914
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/bind/named.conf
rndc configuration: /etc/bind/rndc.conf
DNSSEC root key: /etc/bind/bind.keys
nsupdate session key: //run/named/session.key
named PID file: //run/named/named.pid
named lock file: //run/named/named.lock
geoip-directory: /usr/share/GeoIP
Steps to reproduce
- run
nslookup
- perform several queries, usually only takes 3-4 before the bug exhibits.
What is the current bug behavior?
nslookup doesn't wait for the timeout and immediately responds with the following before attempting again and succeeding.
;; communications error to 0000:0000:000:0000:000:0000:feca:e1ff#53: timed out
Note the IP has been redacted for security reasons, it is a valid global IPv6 address.
Wireshark confirms the request was sent, and nslookup
did not wait for a response.
Once this occurs the first time, it happens for every single dns request until nslookup
is restarted.
Here is the output of nslookup -d2
when this occurs.
> asd.com
addlookup()
make_empty_lookup()
make_empty_lookup() = 0x7ffa2ae00000->references = 1
looking up asd.com
start_lookup()
setup_lookup(0x7ffa2ae00000)
resetting lookup counter.
cloning server list
clone_server_list()
make_server(0000:0000:000:0000:000:0000:feca:e1ff)
idn_textname: asd.com
using root origin
recursive query
add_question()
starting to render the message
done rendering
create query 0x7ffa2ae42000 linked to lookup 0x7ffa2ae00000
dighost.c:2177:lookup_attach(0x7ffa2ae00000) = 2
dighost.c:2690:new_query(0x7ffa2ae42000) = 1
do_lookup()
start_udp(0x7ffa2ae42000)
dighost.c:3301:query_attach(0x7ffa2ae42000) = 2
working on lookup 0x7ffa2ae00000, query 0x7ffa2ae42000
dighost.c:3346:query_attach(0x7ffa2ae42000) = 3
udp_ready()
udp_ready(0x7ffa2ae81000, success, 0x7ffa2ae42000)
lock_lookup dighost.c:3188
success
dighost.c:3189:lookup_attach(0x7ffa2ae00000) = 3
dighost.c:3261:query_attach(0x7ffa2ae42000) = 4
recving with lookup=0x7ffa2ae00000, query=0x7ffa2ae42000, handle=0x7ffa2ae81000
recvcount=1
have local timeout of 5000
dighost.c:3135:query_attach(0x7ffa2ae42000) = 5
sending a request
sendcount=1
dighost.c:1761:query_detach(0x7ffa2ae42000) = 4
dighost.c:3281:query_detach(0x7ffa2ae42000) = 3
dighost.c:3282:lookup_detach(0x7ffa2ae00000) = 2
unlock_lookup dighost.c:3283
send_done(0x7ffa2ae81000, success, 0x7ffa2ae42000)
sendcount=0
lock_lookup dighost.c:2765
success
dighost.c:2769:lookup_attach(0x7ffa2ae00000) = 3
dighost.c:2787:query_detach(0x7ffa2ae42000) = 2
dighost.c:2788:lookup_detach(0x7ffa2ae00000) = 2
check_if_done()
list empty
unlock_lookup dighost.c:2792
recv_done(0x7ffa2ae81000, timed out, 0x7ffa2bdff1c0, 0x7ffa2ae42000)
lock_lookup dighost.c:3955
success
recvcount=0
dighost.c:3960:lookup_attach(0x7ffa2ae00000) = 3
;; communications error to 0000:0000:000:0000:000:0000:feca:e1ff#53: timed out
create query 0x7ffa2ae421c0 linked to lookup 0x7ffa2ae00000
dighost.c:2177:lookup_attach(0x7ffa2ae00000) = 4
dighost.c:4048:new_query(0x7ffa2ae421c0) = 1
making new UDP request, 2 tries left
start_udp(0x7ffa2ae421c0)
dighost.c:3301:query_attach(0x7ffa2ae421c0) = 2
working on lookup 0x7ffa2ae00000, query 0x7ffa2ae421c0
dighost.c:3346:query_attach(0x7ffa2ae421c0) = 3
check_if_queries_done(0x7ffa2ae00000)
there is a pending query 0x7ffa2ae421c0
dighost.c:4554:query_detach(0x7ffa2ae42000) = 1
dighost.c:4562:lookup_detach(0x7ffa2ae00000) = 3
unlock_lookup dighost.c:4566
udp_ready()
udp_ready(0x7ffa2ae81480, success, 0x7ffa2ae421c0)
lock_lookup dighost.c:3188
success
dighost.c:3189:lookup_attach(0x7ffa2ae00000) = 4
dighost.c:3261:query_attach(0x7ffa2ae421c0) = 4
recving with lookup=0x7ffa2ae00000, query=0x7ffa2ae421c0, handle=0x7ffa2ae81480
recvcount=1
have local timeout of 5000
dighost.c:3135:query_attach(0x7ffa2ae421c0) = 5
sending a request
sendcount=1
dighost.c:1761:query_detach(0x7ffa2ae421c0) = 4
dighost.c:3281:query_detach(0x7ffa2ae421c0) = 3
dighost.c:3282:lookup_detach(0x7ffa2ae00000) = 3
unlock_lookup dighost.c:3283
send_done(0x7ffa2ae81480, success, 0x7ffa2ae421c0)
sendcount=0
lock_lookup dighost.c:2765
success
dighost.c:2769:lookup_attach(0x7ffa2ae00000) = 4
dighost.c:2787:query_detach(0x7ffa2ae421c0) = 2
dighost.c:2788:lookup_detach(0x7ffa2ae00000) = 3
check_if_done()
list empty
unlock_lookup dighost.c:2792
recv_done(0x7ffa2ae81480, success, 0x7ffa2bdfbe90, 0x7ffa2ae421c0)
lock_lookup dighost.c:3955
success
recvcount=0
dighost.c:3960:lookup_attach(0x7ffa2ae00000) = 4
before parse starts
after parse
printmessage()
Server: 0000:0000:000:0000:000:0000:feca:e1ff
Address: 0000:0000:000:0000:000:0000:feca:e1ff#53
clone_lookup()
make_empty_lookup()
make_empty_lookup() = 0x7ffa2ae01800->references = 1
Non-authoritative answer:
printsection()
Name: asd.com
Address: 198.46.84.198
still pending.
dighost.c:4554:query_detach(0x7ffa2ae421c0) = 1
dighost.c:4556:_cancel_lookup()
canceling pending query 0x7ffa2ae42000, belonging to 0x7ffa2ae00000
dighost.c:2817:query_detach(0x7ffa2ae42000) = 0
dighost.c:2817:destroy_query(0x7ffa2ae42000) = 0
dighost.c:1719:lookup_detach(0x7ffa2ae00000) = 3
canceling pending query 0x7ffa2ae421c0, belonging to 0x7ffa2ae00000
dighost.c:2817:query_detach(0x7ffa2ae421c0) = 0
dighost.c:2817:destroy_query(0x7ffa2ae421c0) = 0
dighost.c:1719:lookup_detach(0x7ffa2ae00000) = 2
check_if_done()
list full
pending lookup 0x7ffa2ae01800
dighost.c:4562:lookup_detach(0x7ffa2ae00000) = 1
clear_current_lookup()
lookup cleared
dighost.c:1852:lookup_detach(0x7ffa2ae00000) = 0
destroy_lookup
freeing server 0x7ffa2ae27000 belonging to 0x7ffa2ae00000
start_lookup()
setup_lookup(0x7ffa2ae01800)
cloning server list
clone_server_list()
make_server(0000:0000:000:0000:000:0000:feca:e1ff)
idn_textname: asd.com
using root origin
recursive query
add_question()
starting to render the message
done rendering
create query 0x7ffa2ae421c0 linked to lookup 0x7ffa2ae01800
dighost.c:2177:lookup_attach(0x7ffa2ae01800) = 2
dighost.c:2690:new_query(0x7ffa2ae421c0) = 1
do_lookup()
start_udp(0x7ffa2ae421c0)
dighost.c:3301:query_attach(0x7ffa2ae421c0) = 2
working on lookup 0x7ffa2ae01800, query 0x7ffa2ae421c0
dighost.c:3346:query_attach(0x7ffa2ae421c0) = 3
unlock_lookup dighost.c:4566
udp_ready()
udp_ready(0x7ffa2ae81000, success, 0x7ffa2ae421c0)
lock_lookup dighost.c:3188
success
dighost.c:3189:lookup_attach(0x7ffa2ae01800) = 3
dighost.c:3261:query_attach(0x7ffa2ae421c0) = 4
recving with lookup=0x7ffa2ae01800, query=0x7ffa2ae421c0, handle=0x7ffa2ae81000
recvcount=1
have local timeout of 5000
dighost.c:3135:query_attach(0x7ffa2ae421c0) = 5
sending a request
sendcount=1
dighost.c:1761:query_detach(0x7ffa2ae421c0) = 4
dighost.c:3281:query_detach(0x7ffa2ae421c0) = 3
dighost.c:3282:lookup_detach(0x7ffa2ae01800) = 2
unlock_lookup dighost.c:3283
send_done(0x7ffa2ae81000, success, 0x7ffa2ae421c0)
sendcount=0
lock_lookup dighost.c:2765
success
dighost.c:2769:lookup_attach(0x7ffa2ae01800) = 3
dighost.c:2787:query_detach(0x7ffa2ae421c0) = 2
dighost.c:2788:lookup_detach(0x7ffa2ae01800) = 2
check_if_done()
list empty
unlock_lookup dighost.c:2792
recv_done(0x7ffa2ae81000, success, 0x7ffa2bdfbe90, 0x7ffa2ae421c0)
lock_lookup dighost.c:3955
success
recvcount=0
dighost.c:3960:lookup_attach(0x7ffa2ae01800) = 3
before parse starts
after parse
printmessage()
still pending.
dighost.c:4554:query_detach(0x7ffa2ae421c0) = 1
dighost.c:4556:_cancel_lookup()
canceling pending query 0x7ffa2ae421c0, belonging to 0x7ffa2ae01800
dighost.c:2817:query_detach(0x7ffa2ae421c0) = 0
dighost.c:2817:destroy_query(0x7ffa2ae421c0) = 0
dighost.c:1719:lookup_detach(0x7ffa2ae01800) = 2
check_if_done()
list empty
dighost.c:4562:lookup_detach(0x7ffa2ae01800) = 1
clear_current_lookup()
lookup cleared
dighost.c:1852:lookup_detach(0x7ffa2ae01800) = 0
destroy_lookup
freeing server 0x7ffa2ae27000 belonging to 0x7ffa2ae01800
start_lookup()
check_if_done()
list empty
shutting down
dighost_shutdown()
unlock_lookup dighost.c:4566
What is the expected correct behavior?
No communication error and bind to wait up to 5 seconds for the DNS server to respond instead of giving up instantly.
Relevant configuration files
resolv.conf:
search guest.ktmba. inf.ktmba. office.redacted.com.
nameserver 0000:0000:000:0000:000:0000:feca:e1ff
Relevant logs and/or screenshots
Wireshark confirming that nslookup
did not wait at all for a timeout before retrying, resulting in the DNS server responding twice, resulting in the unreachable response for the first request nslookup
didn't wait for.