BIND issueshttps://gitlab.isc.org/isc-projects/bind9/-/issues2022-05-30T12:17:58Zhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3344ThreadSanitizer: data race lib/isc/netmgr/tcpdns.c:1091:12 in isc__nm_tcpdns_...2022-05-30T12:17:58ZMichal NowakThreadSanitizer: data race lib/isc/netmgr/tcpdns.c:1091:12 in isc__nm_tcpdns_sendJob [#2502181](https://gitlab.isc.org/isc-private/bind9/-/jobs/2502181) failed for 4df5a54e9b61aa6fd8b9dad3adaa1d39340ae62b on the `v9_16_sub` branch, which is basically 9.16.28-S1.
```
WARNING: ThreadSanitizer: data race
Read of size...Job [#2502181](https://gitlab.isc.org/isc-private/bind9/-/jobs/2502181) failed for 4df5a54e9b61aa6fd8b9dad3adaa1d39340ae62b on the `v9_16_sub` branch, which is basically 9.16.28-S1.
```
WARNING: ThreadSanitizer: data race
Read of size 8 at 0x000000000001 by thread T1:
#0 isc__nm_tcpdns_send lib/isc/netmgr/tcpdns.c:1091:12
#1 isc_nm_send lib/isc/netmgr/netmgr.c:2438:3
#2 client_sendpkg lib/ns/client.c:355:2
#3 ns_client_send lib/ns/client.c:697:3
#4 query_send lib/ns/query.c:584:2
#5 ns_query_done lib/ns/query.c:11959:2
#6 query_respond lib/ns/query.c:8435:10
#7 query_prepresponse lib/ns/query.c:10969:10
#8 query_gotanswer lib/ns/query.c
#9 query_resume lib/ns/query.c:6886:10
#10 fetch_callback lib/ns/query.c:6442:12
#11 task_run lib/isc/task.c:851:5
#12 isc_task_run lib/isc/task.c:944:10
#13 process_netievent lib/isc/netmgr/netmgr.c
#14 process_queue lib/isc/netmgr/netmgr.c:1040:16
#15 process_all_queues lib/isc/netmgr/netmgr.c:814:25
#16 async_cb lib/isc/netmgr/netmgr.c:842:6
#17 uv__async_io /usr/src/libuv-v1.43.0/src/unix/async.c:163:5
#18 isc__trampoline_run lib/isc/trampoline.c:209:11
Previous write of size 8 at 0x000000000001 by thread T2:
#0 isc__nm_tcpdns_send lib/isc/netmgr/tcpdns.c:1092:23
#1 isc_nm_send lib/isc/netmgr/netmgr.c:2438:3
#2 client_sendpkg lib/ns/client.c:355:2
#3 ns_client_send lib/ns/client.c:697:3
#4 query_send lib/ns/query.c:584:2
#5 ns_query_done lib/ns/query.c:11959:2
#6 query_respond lib/ns/query.c:8435:10
#7 query_prepresponse lib/ns/query.c:10969:10
#8 query_gotanswer lib/ns/query.c
#9 query_resume lib/ns/query.c:6886:10
#10 fetch_callback lib/ns/query.c:6442:12
#11 task_run lib/isc/task.c:851:5
#12 isc_task_run lib/isc/task.c:944:10
#13 process_netievent lib/isc/netmgr/netmgr.c
#14 process_queue lib/isc/netmgr/netmgr.c:1040:16
#15 process_all_queues lib/isc/netmgr/netmgr.c:814:25
#16 async_cb lib/isc/netmgr/netmgr.c:842:6
#17 uv__async_io /usr/src/libuv-v1.43.0/src/unix/async.c:163:5
#18 isc__trampoline_run lib/isc/trampoline.c:209:11
Location is heap block of size 1361 at 0x000000000018 allocated by thread T3:
#0 malloc <null>
#1 default_memalloc lib/isc/mem.c:715:8
#2 mem_get lib/isc/mem.c:624:8
#3 mem_allocateunlocked lib/isc/mem.c:1289:8
#4 isc___mem_allocate lib/isc/mem.c:1309:7
#5 isc__mem_allocate lib/isc/mem.c:2399:10
#6 isc___mem_get lib/isc/mem.c:1059:11
#7 isc__mem_get lib/isc/mem.c:2378:10
#8 accept_connection lib/isc/netmgr/tcpdns.c:956:10
#9 tcpdns_connection_cb lib/isc/netmgr/tcpdns.c:624:11
#10 uv__server_io /usr/src/libuv-v1.43.0/src/unix/stream.c:570:5
#11 isc__trampoline_run lib/isc/trampoline.c:209:11
Thread T1 (running) created by main thread at:
#0 pthread_create <null>
#1 isc_thread_create lib/isc/pthreads/thread.c:81:8
#2 isc__netmgr_create lib/isc/netmgr/netmgr.c:370:3
#3 isc_managers_create lib/isc/managers.c:35:2
#4 create_managers bin/named/./main.c:931:11
#5 setup bin/named/./main.c:1256:11
#6 main bin/named/./main.c:1576:2
Thread T2 (running) created by main thread at:
#0 pthread_create <null>
#1 isc_thread_create lib/isc/pthreads/thread.c:81:8
#2 isc__netmgr_create lib/isc/netmgr/netmgr.c:370:3
#3 isc_managers_create lib/isc/managers.c:35:2
#4 create_managers bin/named/./main.c:931:11
#5 setup bin/named/./main.c:1256:11
#6 main bin/named/./main.c:1576:2
Thread T3 (running) created by main thread at:
#0 pthread_create <null>
#1 isc_thread_create lib/isc/pthreads/thread.c:81:8
#2 isc__netmgr_create lib/isc/netmgr/netmgr.c:370:3
#3 isc_managers_create lib/isc/managers.c:35:2
#4 create_managers bin/named/./main.c:931:11
#5 setup bin/named/./main.c:1256:11
#6 main bin/named/./main.c:1576:2
SUMMARY: ThreadSanitizer: data race lib/isc/netmgr/tcpdns.c:1091:12 in isc__nm_tcpdns_send
```June 2022 (9.16.30, 9.16.30-S1, 9.18.4, 9.19.2)https://gitlab.isc.org/isc-projects/bind9/-/issues/3341Extended DNS errors timing issue in serve-stale system test2023-07-11T10:00:46ZMichal NowakExtended DNS errors timing issue in serve-stale system test`serve-stale:check data.example (max-stale-ttl default)` test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2501631) because `dig` received `EDE: 3 (Stale Answer): (query within stale refresh time window)` instead of the expec...`serve-stale:check data.example (max-stale-ttl default)` test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2501631) because `dig` received `EDE: 3 (Stale Answer): (query within stale refresh time window)` instead of the expected `EDE: 3 (Stale Answer): (resolver failure)` response; looks like a timing issue on a system under pressure.June 2022 (9.16.30, 9.16.30-S1, 9.18.4, 9.19.2)Matthijs Mekkingmatthijs@isc.orgMatthijs Mekkingmatthijs@isc.orghttps://gitlab.isc.org/isc-projects/bind9/-/issues/3340rpz QNAME rewrite a3-8.tld2 stop on unrecognized qresult in rpz_rewrite() failed2022-05-09T20:50:45ZMichal Nowakrpz QNAME rewrite a3-8.tld2 stop on unrecognized qresult in rpz_rewrite() failed`rpz:checking crashes` system test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2501631) with:
```
I:rpz:checking crashes (9)
I:rpz:performance not checked; queryperf not available
I:rpz:error messages in ns6/named.run starti...`rpz:checking crashes` system test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2501631) with:
```
I:rpz:checking crashes (9)
I:rpz:performance not checked; queryperf not available
I:rpz:error messages in ns6/named.run starting with:
I:rpz:ns6/named.run:09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): rpz QNAME rewrite a3-8.tld2 stop on unrecognized qresult in rpz_rewrite() failed: operation canceled
```
<details><summary>ns6/named.run</summary>
```
09-May-2022 16:15:01.526 clientmgr @0x8024c8000 attach: 3
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(<unknown-query>): query_reset
09-May-2022 16:15:01.526 client @0x802559160 (no-peer): allocate new client
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512: TCP request
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512: using view '_default'
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512: request is not signed
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512: recursion available
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(<unknown-query>): ns_query_start
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): qctx_init
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): client attr:0x2103, query attr:0x303, restarts:0, origqname:a3-8.tld2, timer:0, authdb:0, referral:0
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): ns__query_start
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): query (cache) 'a3-8.tld2/ANY/IN' approved
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_lookup
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_gotanswer
09-May-2022 16:15:01.526 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): rrl=0x0, HAVECOOKIE=0, result=DNS_R_DELEGATION, fname=0x8024ead80(1), is_zone=0, RECURSIONOK=1, query.rpz_st=0x0(0), RRL_CHECKED=0
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_checkrpz
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): rpz_rewrite
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): rpz_ck_dnssec
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_delegation
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_delegation_recurse
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): ns_query_recurse
09-May-2022 16:15:01.526 fetch: a3-8.tld2/ANY
09-May-2022 16:15:01.526 res 0x8024e40c0: attach
09-May-2022 16:15:01.526 res 0x8024e40c0: attach
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): create
09-May-2022 16:15:01.526 log_ns_ttl: fctx 0x8038d7c00: fctx_create: a3-8.tld2 (in 'tld2'?): 1 116
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): join
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): addevent
09-May-2022 16:15:01.526 fetch 0x802c1c080 (fctx 0x8038d7c00(a3-8.tld2/ANY)): created
09-May-2022 16:15:01.526 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): ns_query_done
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): start
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): try fctx->qc=0
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelqueries
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): getaddresses fctx->depth=0
09-May-2022 16:15:01.526 findaddrinfo: found entry 0x8024e4700
09-May-2022 16:15:01.526 fctx 0x8038d7c00(a3-8.tld2/ANY): query
09-May-2022 16:15:01.526 dispatch 0x802530c00: UDP connected (0x802c01200): success
09-May-2022 16:15:01.526 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): connected
09-May-2022 16:15:01.526 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): send
09-May-2022 16:15:01.526 sending packet to 10.53.0.3#31859
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 32311
;; flags: rd; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: e0ad29ea0481b9c30100000062793e05e7d24a8fef7243b5
;; QUESTION SECTION:
;a3-8.tld2. IN ANY
09-May-2022 16:15:01.526 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): sent
09-May-2022 16:15:01.526 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): senddone
09-May-2022 16:15:02.728 dispatch 0x802530c00: UDP response 0x802c01200:timed out:requests 1
09-May-2022 16:15:02.728 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): response
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): timeout
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): query timed out; no response
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): [result: timed out] query canceled in rctx_done(); no response
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelquery
09-May-2022 16:15:02.728 dispatch 0x802530c00: detach: refcount 2
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): resend
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): query
09-May-2022 16:15:02.728 fctx 0x8038d7c00(a3-8.tld2/ANY): timed out
09-May-2022 16:15:02.728 dispatch 0x802530c00: detach: refcount 1
09-May-2022 16:15:02.728 dispatch 0x80252f000: UDP connected (0x802c01400): success
09-May-2022 16:15:02.728 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): connected
09-May-2022 16:15:02.728 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): send
09-May-2022 16:15:02.728 sending packet to 10.53.0.3#31859
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 3478
;; flags: rd; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1084
; COOKIE: e0ad29ea0481b9c30100000062793e05e7d24a8fef7243b5
;; QUESTION SECTION:
;a3-8.tld2. IN ANY
09-May-2022 16:15:02.728 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): sent
09-May-2022 16:15:02.728 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): senddone
09-May-2022 16:15:03.938 dispatch 0x80252f000: UDP response 0x802c01400:timed out:requests 1
09-May-2022 16:15:03.938 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): response
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): timeout
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): query timed out; no response
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): [result: timed out] query canceled in rctx_done(); no response
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelquery
09-May-2022 16:15:03.938 dispatch 0x80252f000: detach: refcount 3
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): resend
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): query
09-May-2022 16:15:03.938 fctx 0x8038d7c00(a3-8.tld2/ANY): timed out
09-May-2022 16:15:03.938 dispatch 0x80252f000: detach: refcount 2
09-May-2022 16:15:03.938 dispatch 0x80252f380: UDP connected (0x802c01200): success
09-May-2022 16:15:03.938 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): connected
09-May-2022 16:15:03.938 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): send
09-May-2022 16:15:03.938 sending packet to 10.53.0.3#31859
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 53246
;; flags: rd; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: e0ad29ea0481b9c30100000062793e05e7d24a8fef7243b5
;; QUESTION SECTION:
;a3-8.tld2. IN ANY
09-May-2022 16:15:03.938 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): sent
09-May-2022 16:15:03.938 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): senddone
09-May-2022 16:15:05.149 dispatch 0x80252f380: UDP response 0x802c01200:timed out:requests 1
09-May-2022 16:15:05.149 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): response
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): timeout
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): query timed out; no response
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): [result: timed out] query canceled in rctx_done(); no response
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelquery
09-May-2022 16:15:05.149 dispatch 0x80252f380: detach: refcount 2
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): resend
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): query
09-May-2022 16:15:05.149 dispatchmgr 0x801c35850: dns_dispatch_createtcp: created TCP dispatch 0x802ca0540
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): connecting via TCP
09-May-2022 16:15:05.149 fctx 0x8038d7c00(a3-8.tld2/ANY): timed out
09-May-2022 16:15:05.149 dispatch 0x80252f380: detach: refcount 1
09-May-2022 16:15:05.149 dispatch 0x802ca0540: TCP connected (0x802ca0540): success
09-May-2022 16:15:05.149 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): connected
09-May-2022 16:15:05.149 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): send
09-May-2022 16:15:05.149 sending packet to 10.53.0.3#31859
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 561
;; flags: rd; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: e0ad29ea0481b9c30100000062793e05e7d24a8fef7243b5
;; QUESTION SECTION:
;a3-8.tld2. IN ANY
09-May-2022 16:15:05.149 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): sent
09-May-2022 16:15:05.149 dispatch 0x802ca0540: detach: refcount 3
09-May-2022 16:15:05.149 resquery 0x80281ec00 (fctx 0x8038d7c00(a3-8.tld2/ANY)): senddone
09-May-2022 16:15:06.967 allocate new control connection
09-May-2022 16:15:06.968 received control channel command 'stats'
09-May-2022 16:15:06.968 dumpstats complete
09-May-2022 16:15:06.968 freeing control connection
09-May-2022 16:15:13.527 shut down hung fetch while resolving 'a3-8.tld2/ANY'
09-May-2022 16:15:13.527 fctx 0x8038d7c00(a3-8.tld2/ANY): shutdown
09-May-2022 16:15:13.527 fctx 0x8038d7c00(a3-8.tld2/ANY): posting control event
09-May-2022 16:15:13.527 fctx 0x8038d7c00(a3-8.tld2/ANY): doshutdown
09-May-2022 16:15:13.527 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelqueries
09-May-2022 16:15:13.527 fctx 0x8038d7c00(a3-8.tld2/ANY): cancelquery
09-May-2022 16:15:13.527 dispatch 0x802ca0540: detach: refcount 2
09-May-2022 16:15:13.528 dispatch 0x802ca0540: detach: refcount 1
09-May-2022 16:15:13.528 fctx 0x8038d7c00(a3-8.tld2/ANY): sendevents
09-May-2022 16:15:13.528 fctx 0x8038d7c00(a3-8.tld2/ANY): event
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): fetch_callback
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): qctx_init
09-May-2022 16:15:13.528 dispatch 0x802ca0540: TCP read:end of file:requests 0, buffers 0
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): client attr:0x2103, query attr:0x3303, restarts:0, origqname:a3-8.tld2, timer:0, authdb:1, referral:0
09-May-2022 16:15:13.528 dispatch 0x802ca0540: shutting down TCP: 10.53.0.3#31859: end of file
09-May-2022 16:15:13.528 dispatch 0x802ca0540: detach: refcount 0
09-May-2022 16:15:13.528 dispatch 0x802ca0540: shutting down; detaching from handle 0x802492c80
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_resume
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): resume from normal recursion
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_gotanswer
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): rrl=0x0, HAVECOOKIE=0, result=ISC_R_CANCELED, fname=0x8024ead80(0), is_zone=0, RECURSIONOK=1, query.rpz_st=0x802503800(0), RRL_CHECKED=0
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_checkrpz
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): rpz_rewrite
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): rpz_ck_dnssec
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): rpz QNAME rewrite a3-8.tld2 stop on unrecognized qresult in rpz_rewrite() failed: operation canceled
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_gotanswer: unexpected error: operation canceled
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): free_devent
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): ns_query_done
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): query failed (operation canceled) for a3-8.tld2/IN/ANY at query.c:7715
09-May-2022 16:15:13.528 fetch completed at resolver.c:4523 for a3-8.tld2/ANY in 12.001602: operation canceled/success [domain:tld2,referral:0,restart:1,qrysent:4,timeout:3,lame:0,quota:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:0]
09-May-2022 16:15:13.528 fetch 0x802c1c080 (fctx 0x8038d7c00(a3-8.tld2/ANY)): destroyfetch
09-May-2022 16:15:13.528 fctx 0x8038d7c00(a3-8.tld2/ANY): destroy
09-May-2022 16:15:13.528 res 0x8024e40c0: detach
09-May-2022 16:15:13.528 res 0x8024e40c0: detach
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): send failed: operation canceled
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512 (a3-8.tld2): reset client
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(a3-8.tld2/ANY): query_reset
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(<unknown-query>): rpz_st_clear
09-May-2022 16:15:13.528 client @0x802559160 10.53.0.6#43512: freeing client
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(<unknown-query>): query_reset
09-May-2022 16:15:13.528 query client=0x802559160 thread=0x801c13400(<unknown-query>): rpz_st_clear
09-May-2022 16:15:13.528 clientmgr @0x8024c8000 detach: 2
```
</details>Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3338zero system test fails often2022-10-05T08:30:56ZMichal Nowakzero system test fails oftenThe `zero:check lookups against TTL=0 records` system test [fails](https://gitlab.isc.org/isc-private/bind9/-/jobs/2500945) fairly often on `main` and `v9_18` in the CI (tho I was unable to reproduce it locally):
```
I:zero:check lookups...The `zero:check lookups against TTL=0 records` system test [fails](https://gitlab.isc.org/isc-private/bind9/-/jobs/2500945) fairly often on `main` and `v9_18` in the CI (tho I was unable to reproduce it locally):
```
I:zero:check lookups against TTL=0 records (1)
I:zero:failed
```
Looking at the code there are two possibilities to fail the test code:
1. Either of six `dig -f query.list` instances fails to finish in 69 seconds (`timeout=$(($(wc -l < query.list) / 5))`), or
2. `status: SERVFAIL` is identified in `dig` stdout logs (`dig.out$i.[1-6].test$n`).
Looking at `dig.out$i.[1-6].test$n` logs I am certain that they don't contain `status: SERVFAIL` for any query from the `query.list` file. Perhaps one of six `dig -f query.list` instances is stuck, waiting for being collected by `kill -TERM "$pid1" ...` and `wait "$pid1" || ret=1`?Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3337doth "testing incoming XoT functionality" tests fail2022-07-18T09:43:06ZMichal Nowakdoth "testing incoming XoT functionality" tests failThe `doth:testing incoming XoT functionality (from the first secondary, StrictTLS via specified IPv4)` test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2500946) with `timed out waiting for zone transfer`. Looks like a timing...The `doth:testing incoming XoT functionality (from the first secondary, StrictTLS via specified IPv4)` test [failed](https://gitlab.isc.org/isc-private/bind9/-/jobs/2500946) with `timed out waiting for zone transfer`. Looks like a timing issue.
`dig` failed to transfer the `example5` zone from NS2 via AXFR (`; Transfer failed`); the last attempt:
```
09-May-2022 09:16:26.745 clientmgr @0x8024c8120 attach: 2
09-May-2022 09:16:26.745 query client=0x8031e6000 thread=0x801c14300(<unknown-query>): query_reset
09-May-2022 09:16:26.745 client @0x8031e6000 (no-peer): allocate new client
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685: TCP request
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685: using view '_default'
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685: request is not signed
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685: recursion not available
09-May-2022 09:16:26.746 query client=0x8031e6000 thread=0x801c14300(<unknown-query>): ns_query_start
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685 (example5): AXFR request
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685 (example5): zone transfer setup failed
09-May-2022 09:16:26.746 client @0x8031e6000 10.53.0.10#34685 (example5): reset client
09-May-2022 09:16:26.746 query client=0x8031e6000 thread=0x801c14300(example5/AXFR): query_reset
09-May-2022 09:16:26.747 client @0x8031e6000 10.53.0.10#34685: freeing client
09-May-2022 09:16:26.747 query client=0x8031e6000 thread=0x801c14300(<unknown-query>): query_reset
09-May-2022 09:16:26.747 clientmgr @0x8024c8120 detach: 1
```
This is because NS2, secondary for the `example5` zone, at 9:16:26, last time `dig` tried to transfer the zone, didn't have the zone transfered from NS1 (primary for `example5`) yet:
```
09-May-2022 09:16:04.154 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer status: end of file
09-May-2022 09:16:04.154 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer completed: 0 messages, 0 records, 0 bytes, 0.009 secs (0 bytes/sec) (serial 0)
09-May-2022 09:16:04.700 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer status: TLS error
09-May-2022 09:16:04.700 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer completed: 1 messages, 599 records, 9926 bytes, 0.031 secs (320193 bytes/sec) (serial 1397051952)
09-May-2022 09:17:00.792 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer status: success
09-May-2022 09:17:00.792 transfer of 'example5/IN' from 10.53.0.1#30853: Transfer completed: 5 messages, 2676 records, 55620 bytes, 0.151 secs (368344 bytes/sec) (serial 1397051952)
```
It might be safer to wait for the zone to be present on the secondary server (look for `transfer of '<zone>/IN'.*Transfer status: success`) than poll it via `dig`.August 2022 (9.16.32, 9.16.32-S1, 9.18.6, 9.19.4)Artem BoldarievArtem Boldarievhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3335Confusing parental-source documentation2022-05-16T11:54:19ZMatthijs Mekkingmatthijs@isc.orgConfusing parental-source documentationparental-source determines which local source address, and optionally UDP port, is used to send parental DS queries. **This address must appear in the secondary server’s parental-agents zone clause.** This statement sets the parental-sou...parental-source determines which local source address, and optionally UDP port, is used to send parental DS queries. **This address must appear in the secondary server’s parental-agents zone clause.** This statement sets the parental-source for all zones, but can be overridden on a per-zone or per-view basis by including a parental-source statement within the zone or view block in the configuration file.
The bold line is a copy paste error from `notify-source`.June 2022 (9.16.30, 9.16.30-S1, 9.18.4, 9.19.2)Matthijs Mekkingmatthijs@isc.orgMatthijs Mekkingmatthijs@isc.orghttps://gitlab.isc.org/isc-projects/bind9/-/issues/3331[ISC-support #20639] Problems arising from leading underscores used in QNAME ...2023-07-05T08:41:46ZEverett Fulton[ISC-support #20639] Problems arising from leading underscores used in QNAME minimizationhttps://support.isc.org/Ticket/Display.html?id=20639
(This ticket also involves some odd behavior by the authoritative servers, which is not pertinent to this issue.)
The present method of determining the zone cuts using queries contain...https://support.isc.org/Ticket/Display.html?id=20639
(This ticket also involves some odd behavior by the authoritative servers, which is not pertinent to this issue.)
The present method of determining the zone cuts using queries containing a leading underscore, could be improved upon by using NS queries instead.
Per Mark A:
> I suspect this is an inherent side effect of using '_' prefix labels. We don't get a negative cache entry for the intermediate node to know that we don't need to query for it. Going back to direct NS queries would be the way to fix this by looking for the lack of a non existance for the NS RRset in the cache before making the probe.July 2023 (9.18.17, 9.18.17-S1, 9.19.15)https://gitlab.isc.org/isc-projects/bind9/-/issues/3329ADB uses recursion when auth zone is not ready2022-06-02T11:21:16ZCathy AlmondADB uses recursion when auth zone is not readyAs reported in [Support ticket #20672](https://support.isc.org/Ticket/Display.html?id=20672)
The bug was originally found in 9.11, but still exists in 9.16.
Quoting the reporter (almost) verbatim:
We found a bug where when a locally c...As reported in [Support ticket #20672](https://support.isc.org/Ticket/Display.html?id=20672)
The bug was originally found in 9.11, but still exists in 9.16.
Quoting the reporter (almost) verbatim:
We found a bug where when a locally configured authoritative zone was
not ready, ADB would try to resolve NS addresses whose names were under
such zones using the resolver and cache results (e.g., NXDOMAIN) within
the ADB cache. Whereas it should not, and it should fail such lookups
until the local zone database is ready.
This behavior of ADB was implemented differently from the query path.
The bug was readily reproducible by the customer who was using a custom
dns_db database implementation.
This caused resolution failures for upto NCACHE TTL (e.g.,
min(SOA.minimum TTL, SOA TTL)) in our customer's case (15 minutes).
in "our distribution (redacted)" with a unittest (similar to
ISC BIND system test) to reproduce it, but I am unable to share the
testcase code right now. The testcase is anyway reliant on the rest of
"our distribution (redacted)" test framework, so I don't know how useful it would
be to ISC. BUT, the testcase used database type "rbt" as in ISC BIND.
An extract of patch we used to fix it, which may be helpful to
understand the problem:
```
diff --git a/lib/dns/adb.c b/lib/dns/adb.c
index ea93fef..bdd514c 100644
--- a/lib/dns/adb.c
+++ b/lib/dns/adb.c
@@ -3177,6 +3177,25 @@ dns_adb_createfind(dns_adb_t *adb, isc_task_t *task, isc_taskaction_t action,
if (!NAME_FETCH_V4(adbname)) {
wanted_fetches |= DNS_ADBFIND_INET;
}
+
+ /*
+ * If a dbfind_name() resulted in DNS_R_NOTLOADED, it
+ * would have happened because a zone database was not
+ * yet loaded (e.g., during named startup). In this
+ * case, don't attempt any fetches to avoid caching any
+ * results from recursion that may return undesired data
+ * vs. what is in the local zones.
+ *
+ * This may cause short-lived failures, but it is better
+ * than long-term failures, e.g., due to NXDOMAIN
+ * answers from upstream forwarders when looking up the
+ * addresses of nameservers because they don't exist
+ * outside local zones, that are cached for multiple
+ * minutes and cause SERVFAIL to downstream clients
+ * until their NCACHE TTL expire.
+ */
+ if (ISC_UNLIKELY(result == DNS_R_NOTLOADED))
+ find->options |= DNS_ADBFIND_NOFETCH;
}
v6:
@@ -3213,6 +3232,12 @@ v6:
if (!NAME_FETCH_V6(adbname)) {
wanted_fetches |= DNS_ADBFIND_INET6;
}
+
+ /*
+ * See similar comment in IPv4 case above.
+ */
+ if (ISC_UNLIKELY(result == DNS_R_NOTLOADED))
+ find->options |= DNS_ADBFIND_NOFETCH;
}
fetch:
diff --git a/lib/dns/view.c b/lib/dns/view.c
index 4a8f9af..c0e7f80 100644
--- a/lib/dns/view.c
+++ b/lib/dns/view.c
@@ -1091,6 +1091,9 @@ dns_view_find(dns_view_t *view, const dns_name_t *name, dns_rdatatype_t type,
}
if (result == ISC_R_SUCCESS || result == DNS_R_PARTIALMATCH) {
result = dns_zone_getdb(zone, &db);
+ if (result == DNS_R_NOTLOADED) {
+ goto cleanup;
+ }
if (result != ISC_R_SUCCESS && view->cachedb != NULL) {
dns_db_attach(view->cachedb, &db);
} else if (result != ISC_R_SUCCESS) {
```Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3327fetches-per-server has been broken since 9.162022-06-15T13:45:59ZEvan Huntfetches-per-server has been broken since 9.16While working on another issue I noticed the output of the `fetchlimit` system test didn't match my recollection of how it used to look. I've almost certainly seen this before, but it didn't rise to the level of consciousness that would ...While working on another issue I noticed the output of the `fetchlimit` system test didn't match my recollection of how it used to look. I've almost certainly seen this before, but it didn't rise to the level of consciousness that would prompt me to confirm, but this time it did, and sure enough, up until 9.15.7 the test output looked like this:
```
I:fetchlimit:checking recursing clients are dropped at the per-server limit
I:fetchlimit:clients: 20
I:fetchlimit:clients: 40
I:fetchlimit:clients: 60
I:fetchlimit:clients: 80
I:fetchlimit:clients: 100
I:fetchlimit:clients: 120
I:fetchlimit:clients: 140
I:fetchlimit:clients: 160
I:fetchlimit:clients: 180
I:fetchlimit:clients: 180
I:fetchlimit:clients: 180
I:fetchlimit:clients: 177
I:fetchlimit:clients: 165
I:fetchlimit:clients: 152
I:fetchlimit:clients: 141
I:fetchlimit:clients: 131
I:fetchlimit:clients: 122
I:fetchlimit:clients: 114
I:fetchlimit:clients: 114
I:fetchlimit:clients: 107
```
...but now it's this:
```
I:fetchlimit:checking recursing clients are dropped at the per-server limit
I:fetchlimit:clients: 20
I:fetchlimit:clients: 40
I:fetchlimit:clients: 60
I:fetchlimit:clients: 80
I:fetchlimit:clients: 28
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
I:fetchlimit:clients: 0
```
This is due to a logic error introduced in `maybe_adjust_quota()` in commit bad5a523c2e: Instead of updating the quota to the calculated `new_quota`, it's updated to `ISC_MIN(1, new_quota)`, which effectively means always 1. The test was only checking that the number of clients was below the specified limit, not that it was above a reasonable minimum, and so the error went unnoticed.
I would guess this has probably had some impact on recursive performance.June 2022 (9.16.30, 9.16.30-S1, 9.18.4, 9.19.2)Evan HuntEvan Hunthttps://gitlab.isc.org/isc-projects/bind9/-/issues/3326underscore qname minimisation mode should query for NS when returned SOA name...2023-07-05T08:41:46ZMark Andrewsunderscore qname minimisation mode should query for NS when returned SOA name is below the current domainWhen a parent zone hosts a child zone underscore qname minimisation doesn't learn the intermediate NS RRsets leading to extra traffic. If we get an indication of a deeper zone (e.g. returned SOA name below the current domain) query for t...When a parent zone hosts a child zone underscore qname minimisation doesn't learn the intermediate NS RRsets leading to extra traffic. If we get an indication of a deeper zone (e.g. returned SOA name below the current domain) query for the NS RRset so that future queries start deeper in the tree.July 2023 (9.18.17, 9.18.17-S1, 9.19.15)https://gitlab.isc.org/isc-projects/bind9/-/issues/3325strict qname minimisation should check for cached NODATA for NS name2023-07-05T08:19:08ZMark Andrewsstrict qname minimisation should check for cached NODATA for NS nameIn strict qname minimisation mode we should check for cached NODATA for NS records at the name when computing the next intermediate name and move onto the next name if found.In strict qname minimisation mode we should check for cached NODATA for NS records at the name when computing the next intermediate name and move onto the next name if found.July 2023 (9.18.17, 9.18.17-S1, 9.19.15)https://gitlab.isc.org/isc-projects/bind9/-/issues/3324clean up fctx_minimize_qname2022-06-02T11:15:31ZMark Andrewsclean up fctx_minimize_qnameThere are redundant variables and multiple initialisations of the same variable when constructing the next qminname.There are redundant variables and multiple initialisations of the same variable when constructing the next qminname.Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3323BIND 9.16.23-S1 different RPZ SOA TTL2022-06-02T11:21:23ZGreg ChoulesBIND 9.16.23-S1 different RPZ SOA TTLReported to us in [Support ticket #20670](https://support.isc.org/Ticket/Display.html?id=20670)
An RPZ response's SOA record TTL is set to 1 instead of the SOA TTL, due to what seems to be incorrectly modified code (from the difference...Reported to us in [Support ticket #20670](https://support.isc.org/Ticket/Display.html?id=20670)
An RPZ response's SOA record TTL is set to 1 instead of the SOA TTL, due to what seems to be incorrectly modified code (from the difference in types). A bool value is passed to **query_addsoa()** in an argument that expects unsigned int.
The diff below is from the BIND 9.16.23-S1 tree:
```
9.16.23-S1 (main)]$ git diff
diff --git a/lib/ns/query.c b/lib/ns/query.c
index ca1ffe4..f9e0f2b 100644
--- a/lib/ns/query.c
+++ b/lib/ns/query.c
@@ -7454,9 +7454,7 @@ query_checkrpz(query_ctx_t *qctx, isc_result_t result) {
* Add SOA record to additional section
*/
if (qctx->rpz_st->m.rpz->addsoa) {
- bool override_ttl =
- dns_rdataset_isassociated(qctx->rdataset);
- rresult = query_addsoa(qctx, override_ttl,
+ rresult = query_addsoa(qctx, UINT32_MAX,
DNS_SECTION_ADDITIONAL);
if (rresult != ISC_R_SUCCESS) {
QUERY_ERROR(qctx, result);
```Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3322BIND 9.16 startup crash (with two views with the same name but different clas...2023-06-05T14:26:41ZCathy AlmondBIND 9.16 startup crash (with two views with the same name but different classes)Reported to us in [Support ticket #20669](https://support.isc.org/Ticket/Display.html?id=20669)
As explained by the reporter (and testing against 9.16.23-S1, but likely affecting all current versions of BIND):
named crashes at startup ...Reported to us in [Support ticket #20669](https://support.isc.org/Ticket/Display.html?id=20669)
As explained by the reporter (and testing against 9.16.23-S1, but likely affecting all current versions of BIND):
named crashes at startup with a config file such as this:
```
view "test" in {
recursion no;
notify no;
};
view "test" chaos {
recursion no;
notify no;
};
```
The root cause appears to be due to the managed-keys KEYDATA zone file's
filename containing only the view's name and not the view's class.Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3320Rewrite ARM DNSSEC Chapter2022-07-07T08:39:09ZMatthijs Mekkingmatthijs@isc.orgRewrite ARM DNSSEC ChapterJuly 2022 (9.16.31, 9.16.31-S1, 9.18.5, 9.19.3)Matthijs Mekkingmatthijs@isc.orgMatthijs Mekkingmatthijs@isc.orghttps://gitlab.isc.org/isc-projects/bind9/-/issues/3318typo in rndc man page2022-05-16T10:46:29ZMark Andrewstypo in rndc man page`withdraw` should be `withdrawn`
```
-.. option:: dnssec (-status | -rollover -key id [-alg algorithm] [-when time] | -checkds [-key id [-alg algorithm]] [-when time] published | withdraw)) zone [class [view]]
+.. option:: dnssec (-stat...`withdraw` should be `withdrawn`
```
-.. option:: dnssec (-status | -rollover -key id [-alg algorithm] [-when time] | -checkds [-key id [-alg algorithm]] [-when time] published | withdraw)) zone [class [view]]
+.. option:: dnssec (-status | -rollover -key id [-alg algorithm] [-when time] | -checkds [-key id [-alg algorithm]] [-when time] published | withdrawn)) zone [class [view]]
```May 2022 (9.16.29, 9.16.29-S1, 9.18.3, 9.19.1)https://gitlab.isc.org/isc-projects/bind9/-/issues/3317CID 352554 (#1 of 1): Dereference before null check (REVERSE_INULL)2022-05-16T10:48:02ZMark AndrewsCID 352554 (#1 of 1): Dereference before null check (REVERSE_INULL)```
3034 next = ISC_LIST_NEXT(query, link);
3035 } else {
3036 next = NULL;
3037 }
CID 352554 (#1 of 1): Dereference before null check (REVERSE_INULL)
check_after_deref: Null-checking con...```
3034 next = ISC_LIST_NEXT(query, link);
3035 } else {
3036 next = NULL;
3037 }
CID 352554 (#1 of 1): Dereference before null check (REVERSE_INULL)
check_after_deref: Null-checking connectquery suggests that it may be null, but it has already been dereferenced on all paths leading to the check.
3038 if (connectquery != NULL) {
3039 query_detach(&connectquery);
3040 }
```May 2022 (9.16.29, 9.16.29-S1, 9.18.3, 9.19.1)https://gitlab.isc.org/isc-projects/bind9/-/issues/3310Build contrib in CI2022-11-23T18:23:14ZMichal NowakBuild contrib in CIisc-projects/bind9#3306 is an example of build issue which we missed because we don't build the `contrib/` directory in the CI, and we should.
This requires additional dependencies to the default CI image and code fixes (e.g. isc-projec...isc-projects/bind9#3306 is an example of build issue which we missed because we don't build the `contrib/` directory in the CI, and we should.
This requires additional dependencies to the default CI image and code fixes (e.g. isc-projects/bind9#3306, isc-projects/bind9#2813).
```shell
for d in contrib/dlz/modules/*; do
[ -e $d/Makefile ] && make -C $d
done
```December 2022 (9.16.36, 9.16.36-S1, 9.18.10, 9.19.8)Michal NowakMichal Nowakhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3309Destination port is missing from dnstap captures of client traffic2022-06-22T11:54:38ZMichał KępieńDestination port is missing from dnstap captures of client trafficWith the following configuration:
```
options {
listen-on port 5300 { 127.0.0.1; };
listen-on-v6 port 5300 { ::1; };
dnstap { client; };
dnstap-output file "dnstap.log";
};
```
`named` produces the following dnstap data:
```
$ dns...With the following configuration:
```
options {
listen-on port 5300 { 127.0.0.1; };
listen-on-v6 port 5300 { ::1; };
dnstap { client; };
dnstap-output file "dnstap.log";
};
```
`named` produces the following dnstap data:
```
$ dnstap-read dnstap.log
27-Apr-2022 13:25:53.672 CQ ::1:36670 -> ::1:0 UDP 48b isc.org/IN/A
27-Apr-2022 13:25:53.675 CQ 127.0.0.1:53203 -> 127.0.0.1:0 UDP 48b isc.org/IN/A
27-Apr-2022 13:25:53.998 CR ::1:36670 <- ::1:0 UDP 80b isc.org/IN/A
27-Apr-2022 13:25:53.998 CR 127.0.0.1:53203 <- 127.0.0.1:0 UDP 80b isc.org/IN/A
```
Note the `::1:0` and `127.0.0.1:0`. The proper, expected data is:
```
$ dnstap-read dnstap.log
27-Apr-2022 13:27:04.725 CQ ::1:58931 -> ::1:5300 UDP 48b isc.org/IN/A
27-Apr-2022 13:27:04.725 CQ 127.0.0.1:44892 -> 127.0.0.1:5300 UDP 48b isc.org/IN/A
27-Apr-2022 13:27:05.215 CR ::1:58931 <- ::1:5300 UDP 80b isc.org/IN/A
27-Apr-2022 13:27:05.215 CR 127.0.0.1:44892 <- 127.0.0.1:5300 UDP 80b isc.org/IN/A
```July 2022 (9.16.31, 9.16.31-S1, 9.18.5, 9.19.3)Michał KępieńMichał Kępieńhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3308CI job timeout while system tests were running2023-03-17T08:47:32ZMichal NowakCI job timeout while system tests were runningThe CI job [2471391](https://gitlab.isc.org/isc-projects/bind9/-/jobs/2471391) reached a CI job timeout while four system test were running.
It's like isc-projects/bind9#3272 but the failed CI job did not happen in ASAN/TSAN environment...The CI job [2471391](https://gitlab.isc.org/isc-projects/bind9/-/jobs/2471391) reached a CI job timeout while four system test were running.
It's like isc-projects/bind9#3272 but the failed CI job did not happen in ASAN/TSAN environment but on OpenBSD and the `shutdown` system pytest actually passed.
```
$ curl -sSL https://gitlab.isc.org/isc-projects/bind9/-/jobs/2471391/raw | grep '^[SR]:' | cut -d: -f2 | sort | uniq -c | awk '$1 != "2" { print }'
1 forward
1 geoip2
1 inline
1 kasp
```
The job started at 6:07, last system test time stamp is from 6:15:53:
```
$ curl -sSL https://gitlab.isc.org/isc-projects/bind9/-/jobs/2471391/raw | grep -P '^(S|E):.*:'
S:logfileconfig:2022-04-27T06:08:03+0000
S:keymgr:2022-04-27T06:08:03+0000
S:coverage:2022-04-27T06:08:03+0000
S:cookie:2022-04-27T06:08:03+0000
...
E:ixfr:2022-04-27T06:15:53+0000
S:forward:2022-04-27T06:15:53+0000
```
```
S:forward:2022-04-27T06:15:53+0000
T:forward:1:A
A:forward:System test forward
I:forward:PORTRANGE:8200 - 8299
I:forward:starting servers
```
```
S:geoip2:2022-04-27T06:15:45+0000
T:geoip2:1:A
A:geoip2:System test geoip2
I:geoip2:PORTRANGE:8300 - 8399
I:geoip2:starting servers
I:geoip2:checking that conf/good-options.conf is accepted (1)
I:geoip2:checking that conf/bad-areacode.conf is rejected (2)
I:geoip2:checking that conf/bad-dbname.conf is rejected (3)
I:geoip2:checking that conf/bad-netspeed.conf is rejected (4)
I:geoip2:checking that conf/bad-regiondb.conf is rejected (5)
I:geoip2:checking that conf/bad-threeletter.conf is rejected (6)
I:geoip2:checking Country database by code using IPv4 (7)
I:geoip2:checking Country database by code using IPv6 (8)
I:geoip2:reloading server
I:geoip2:ns2 server reload successful
I:geoip2:checking Country database with nested ACLs using IPv4 (9)
I:geoip2:checking Country database with nested ACLs using IPv6 (10)
I:geoip2:reloading server
I:geoip2:ns2 server reload successful
I:geoip2:checking Country database by name using IPv4 (11)
I:geoip2:checking Country database by name using IPv6 (12)
I:geoip2:reloading server
I:geoip2:ns2 server reload successful
I:geoip2:checking Country database by continent code using IPv4 (13)
```
```
S:inline:2022-04-27T06:15:29+0000
T:inline:1:A
A:inline:System test inline
I:inline:PORTRANGE:8600 - 8699
I:inline:starting servers
I:inline:checking that an unsupported algorithm is not used for signing (1)
I:inline:checking that rrsigs are replaced with ksk only (2)
I:inline:checking that the zone is signed on initial transfer (3)
I:inline:checking expired signatures are updated on load (4)
I:inline:checking removal of private type record via 'rndc signing -clear' (5)
I:inline:checking private type was properly signed (6)
I:inline:checking removal of remaining private type record via 'rndc signing -clear all' (7)
I:inline:checking negative private type response was properly signed (8)
I:inline:checking that the record is added on the hidden primary (9)
I:inline:checking that update has been transferred and has been signed (10)
I:inline:checking YYYYMMDDVV (2011072400) serial on hidden primary (11)
I:inline:checking YYYYMMDDVV (2011072400) serial in signed zone (12)
I:inline:checking that the zone is signed on initial transfer, noixfr (13)
I:inline:checking that the record is added on the hidden primary, noixfr (14)
I:inline:checking that update has been transferred and has been signed, noixfr (15)
I:inline:checking YYYYMMDDVV (2011072400) serial on hidden primary, noixfr (16)
I:inline:checking YYYYMMDDVV (2011072400) serial in signed zone, noixfr (17)
I:inline:checking that the primary zone signed on initial load (18)
I:inline:checking removal of private type record via 'rndc signing -clear' (primary) (19)
I:inline:checking private type was properly signed (primary) (20)
I:inline:checking removal of remaining private type record via 'rndc signing -clear' (primary) (21)
I:inline:check adding of record to unsigned primary (22)
I:inline:ns3 zone reload queued
I:inline:check adding record fails when SOA serial not changed (23)
I:inline:ns3 server reload successful
I:inline:check adding record works after updating SOA serial (24)
```
<details><summary>kasp</summary>
```
S:kasp:2022-04-27T06:15:07+0000
T:kasp:1:A
A:kasp:System test kasp
I:kasp:PORTRANGE:9000 - 9099
I:kasp:This test requires support for EDDSA cryptography
I:kasp:configure with --with-openssl, or --enable-native-pkcs11 --with-pkcs11
I:kasp:This test requires support for EDDSA cryptography
I:kasp:configure with --with-openssl, or --enable-native-pkcs11 --with-pkcs11
I:kasp:starting servers
I:kasp:check that 'dnssec-keygen -k' (configured policy) creates valid files (1)
I:kasp:check that 'dnssec-keygen -k' (default policy) creates valid files (2)
I:kasp:check key file ./Kkasp.+013+51983
I:kasp:check key timing metadata for key KEY1 id 51983 zone kasp (3)
I:kasp:check that 'dnssec-settime' by default does not edit key state file (4)
I:kasp:check that 'dnssec-settime -s' also sets publish time metadata and states in key state file (5)
I:kasp:check key file ./Kkasp.+013+51983
I:kasp:check key timing metadata for key KEY1 id 51983 zone kasp (6)
I:kasp:check that 'dnssec-settime -s' also unsets publish time metadata and states in key state file (7)
I:kasp:check key file ./Kkasp.+013+51983
I:kasp:check key timing metadata for key KEY1 id 51983 zone kasp (8)
I:kasp:check that 'dnssec-settime -s' also sets active time metadata and states in key state file (uppercase) (9)
I:kasp:check key file ./Kkasp.+013+51983
I:kasp:check key timing metadata for key KEY1 id 51983 zone kasp (10)
I:kasp:waiting for kasp signing changes to take effect (11)
I:kasp:check keys are created for zone default.kasp (12)
I:kasp:check number of keys for zone default.kasp in dir ns3 (12)
I:kasp:check key id 39605
I:kasp:KEY1 ID 39605
I:kasp:check rndc dnssec -status output for default.kasp (policy: default) (13)
I:kasp:check key timing metadata for key KEY1 id 39605 zone default.kasp (14)
I:kasp:check DNSKEY rrset is signed correctly for zone default.kasp (15)
I:kasp:check SOA rrset is signed correctly for zone default.kasp (16)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone default.kasp (17)
I:kasp:check A a.default.kasp rrset is signed correctly for zone default.kasp (18)
I:kasp:dnssec-verify zone default.kasp (19)
I:kasp:modify unsigned zone file and check that new record is signed for zone default.kasp (20)
I:kasp:test that if private key files are inaccessible this doesn't trigger a rollover (20)
I:kasp:check keys are created for zone default.kasp (21)
I:kasp:check number of keys for zone default.kasp in dir ns3 (21)
I:kasp:check key id 39605
I:kasp:KEY1 ID 39605
I:kasp:check rndc dnssec -status output for default.kasp (policy: default) (22)
I:kasp:check key timing metadata for key KEY1 id 39605 zone default.kasp (23)
I:kasp:check DNSKEY rrset is signed correctly for zone default.kasp (24)
I:kasp:check SOA rrset is signed correctly for zone default.kasp (25)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone default.kasp (26)
I:kasp:check A a.default.kasp rrset is signed correctly for zone default.kasp (27)
I:kasp:dnssec-verify zone default.kasp (28)
I:kasp:check keys are created for zone dynamic.kasp (29)
I:kasp:check number of keys for zone dynamic.kasp in dir ns3 (29)
I:kasp:check key id 56831
I:kasp:KEY1 ID 56831
I:kasp:check rndc dnssec -status output for dynamic.kasp (policy: default) (30)
I:kasp:check key timing metadata for key KEY1 id 56831 zone dynamic.kasp (31)
I:kasp:check DNSKEY rrset is signed correctly for zone dynamic.kasp (32)
I:kasp:check SOA rrset is signed correctly for zone dynamic.kasp (33)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone dynamic.kasp (34)
I:kasp:check A a.dynamic.kasp rrset is signed correctly for zone dynamic.kasp (35)
I:kasp:dnssec-verify zone dynamic.kasp (36)
I:kasp:nsupdate zone and check that new record is signed for zone dynamic.kasp (37)
I:kasp:nsupdate zone and check that new record is signed for zone dynamic.kasp (38)
I:kasp:modify zone file and check that new record is signed for zone dynamic.kasp (39)
I:kasp:check keys are created for zone dynamic-inline-signing.kasp (40)
I:kasp:check number of keys for zone dynamic-inline-signing.kasp in dir ns3 (40)
I:kasp:check key id 32461
I:kasp:KEY1 ID 32461
I:kasp:check rndc dnssec -status output for dynamic-inline-signing.kasp (policy: default) (41)
I:kasp:check key timing metadata for key KEY1 id 32461 zone dynamic-inline-signing.kasp (42)
I:kasp:check DNSKEY rrset is signed correctly for zone dynamic-inline-signing.kasp (43)
I:kasp:check SOA rrset is signed correctly for zone dynamic-inline-signing.kasp (44)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone dynamic-inline-signing.kasp (45)
I:kasp:check A a.dynamic-inline-signing.kasp rrset is signed correctly for zone dynamic-inline-signing.kasp (46)
I:kasp:dnssec-verify zone dynamic-inline-signing.kasp (47)
I:kasp:modify unsigned zone file and check that new record is signed for zone dynamic-inline-signing.kasp (48)
I:kasp:check keys are created for zone inline-signing.kasp (49)
I:kasp:check number of keys for zone inline-signing.kasp in dir ns3 (49)
I:kasp:check key id 44130
I:kasp:KEY1 ID 44130
I:kasp:check rndc dnssec -status output for inline-signing.kasp (policy: default) (50)
I:kasp:check key timing metadata for key KEY1 id 44130 zone inline-signing.kasp (51)
I:kasp:check DNSKEY rrset is signed correctly for zone inline-signing.kasp (52)
I:kasp:check SOA rrset is signed correctly for zone inline-signing.kasp (53)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone inline-signing.kasp (54)
I:kasp:check A a.inline-signing.kasp rrset is signed correctly for zone inline-signing.kasp (55)
I:kasp:dnssec-verify zone inline-signing.kasp (56)
I:kasp:check keys are created for zone checkds-ksk.kasp (57)
I:kasp:check number of keys for zone checkds-ksk.kasp in dir ns3 (57)
I:kasp:check key id 57464
I:kasp:check key id 12023
I:kasp:KEY1 ID 57464
I:kasp:KEY2 ID 12023
I:kasp:check rndc dnssec -status output for checkds-ksk.kasp (policy: checkds-ksk) (58)
I:kasp:check DNSKEY rrset is signed correctly for zone checkds-ksk.kasp (59)
I:kasp:check SOA rrset is signed correctly for zone checkds-ksk.kasp (60)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone checkds-ksk.kasp (61)
I:kasp:check A a.checkds-ksk.kasp rrset is signed correctly for zone checkds-ksk.kasp (62)
I:kasp:dnssec-verify zone checkds-ksk.kasp (63)
I:kasp:checkds publish correctly sets DSPublish for zone checkds-ksk.kasp (64)
I:kasp:calling rndc dnssec -checkds -when 20190102121314 published zone checkds-ksk.kasp in (65)
I:kasp:checkds withdraw correctly sets DSRemoved for zone checkds-ksk.kasp (66)
I:kasp:calling rndc dnssec -checkds -when 20200102121314 withdrawn zone checkds-ksk.kasp in (67)
I:kasp:check keys are created for zone checkds-doubleksk.kasp (68)
I:kasp:check number of keys for zone checkds-doubleksk.kasp in dir ns3 (68)
I:kasp:check key id 26947
I:kasp:check key id 27455
I:kasp:check key id 07792
I:kasp:KEY1 ID 26947
I:kasp:KEY2 ID 27455
I:kasp:KEY3 ID 7792
I:kasp:check rndc dnssec -status output for checkds-doubleksk.kasp (policy: checkds-doubleksk) (69)
I:kasp:check DNSKEY rrset is signed correctly for zone checkds-doubleksk.kasp (70)
I:kasp:check SOA rrset is signed correctly for zone checkds-doubleksk.kasp (71)
I:kasp:check CDS and CDNSKEY rrset are signed correctly for zone checkds-doubleksk.kasp (72)
```
</details>Not planned