BIND issueshttps://gitlab.isc.org/isc-projects/bind9/-/issues2022-10-20T16:51:28Zhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3602udp_test fails with atomic_load(&sreads) >= expected_creads2022-10-20T16:51:28ZOndřej Surýudp_test fails with atomic_load(&sreads) >= expected_creadsReproduced under `rr record -h`:
```
[==========] Running 18 test(s).
[ RUN ] mock_listenudp_uv_udp_open
[ OK ] mock_listenudp_uv_udp_open
[ RUN ] mock_listenudp_uv_udp_bind
[ OK ] mock_listenudp_uv_udp_bind
[ RUN ...Reproduced under `rr record -h`:
```
[==========] Running 18 test(s).
[ RUN ] mock_listenudp_uv_udp_open
[ OK ] mock_listenudp_uv_udp_open
[ RUN ] mock_listenudp_uv_udp_bind
[ OK ] mock_listenudp_uv_udp_bind
[ RUN ] mock_listenudp_uv_udp_recv_start
[ OK ] mock_listenudp_uv_udp_recv_start
[ RUN ] mock_udpconnect_uv_udp_open
[ OK ] mock_udpconnect_uv_udp_open
[ RUN ] mock_udpconnect_uv_udp_bind
[ OK ] mock_udpconnect_uv_udp_bind
[ RUN ] mock_udpconnect_uv_udp_connect
[ OK ] mock_udpconnect_uv_udp_connect
[ RUN ] mock_udpconnect_uv_recv_buffer_size
[ OK ] mock_udpconnect_uv_recv_buffer_size
[ RUN ] mock_udpconnect_uv_send_buffer_size
[ OK ] mock_udpconnect_uv_send_buffer_size
[ RUN ] udp_noop
[ OK ] udp_noop
[ RUN ] udp_noresponse
[ OK ] udp_noresponse
[ RUN ] udp_shutdown_connect
[ OK ] udp_shutdown_connect
[ RUN ] udp_shutdown_read
[ OK ] udp_shutdown_read
[ RUN ] udp_cancel_read
[ OK ] udp_cancel_read
[ RUN ] udp_timeout_recovery
[ OK ] udp_timeout_recovery
[ RUN ] udp_double_read
[ OK ] udp_double_read
[ RUN ] udp_recv_one
[ OK ] udp_recv_one
[ RUN ] udp_recv_two
[ OK ] udp_recv_two
[ RUN ] udp_recv_send
atomic_load(&sreads) >= expected_creads
[ LINE ] --- udp_test.c:947: error: Failure!Aborted
```Not plannedOndřej SurýOndřej Surýhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3579Add more debugging messages for network-level events2022-10-05T09:37:10ZMichał KępieńAdd more debugging messages for network-level eventsThe network manager code is currently not particularly verbose when it
comes to logging debug messages:
$ git grep isc_log_write lib/isc/netmgr/ | wc -l
9
In particular, this applies to "positive" events (non-errors), like
esta...The network manager code is currently not particularly verbose when it
comes to logging debug messages:
$ git grep isc_log_write lib/isc/netmgr/ | wc -l
9
In particular, this applies to "positive" events (non-errors), like
establishing a connection, correctly receiving data from a socket, etc.
This applies to both non-encrypted transports (like TCP) and encrypted
ones.
The problem for me as an administrator/troubleshooter is that I have
very limited visibility into what BIND 9 "sees" on its side of things
when things go south. For example, I recently experimented with getting
`systemd-resolved` to talk to `named` over DNS-over-TLS; the former
reported, well, *errors*, and I could not get a grasp of the point at
which things are failing without resorting to Wireshark ("Is it the TCP
connection on port 853 itself? Or maybe the TLS session negotiation?
Or is that part okay and it is something about the data that
`system-resolved` sends inside a properly-established TLS session that
makes `named` complain?" etc.)
I am opening this issue so that it can serve as a public acknowledgment
of this being a known deficiency. It would be nice to do something
about it in the log run. Obviously there will have to be performance
trade-offs, but I think even hiding certain log messages behind a
build-time switch is fine as long as there is *some* way of getting
`named` to become more talkative logging-wise when it comes to
network-level events.Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3561Analyze the current lock contention2022-09-26T09:20:18ZOndřej SurýAnalyze the current lock contentionI've hacked `mutrace` and `named` to work again together and here are current results:
```
mutrace: Showing statistics for process named (PID: 1782915).
mutrace: 1802520 mutexes used.
Mutex #1326836 (0x0x55ec3f8dd640) first referenced ...I've hacked `mutrace` and `named` to work again together and here are current results:
```
mutrace: Showing statistics for process named (PID: 1782915).
mutrace: 1802520 mutexes used.
Mutex #1326836 (0x0x55ec3f8dd640) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_sdb_register+0xb7) [0x7fc95ca55f32]
Mutex #1332002 (0x0x55ec3fa3b4e0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(isc__task_create+0xbd) [0x7fc95cb98aee]
Mutex #1329994 (0x0x55ec3f9cea68) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_rbtdb_create+0xfe) [0x7fc95c9e4cfc]
Mutex #1332378 (0x0x55ec3fa5b7a8) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_adb_create+0x120) [0x7fc95c951561]
Mutex #1332379 (0x0x55ec3fa5bd30) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(isc__task_create+0xbd) [0x7fc95cb98aee]
Mutex #1327168 (0x0x55ec3f8f9558) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_zonemgr_create+0x218) [0x7fc95caa36d6]
Mutex #1325497 (0x0x55ec3f841648) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(+0x438b4) [0x7fc95cb8c8b4]
Mutex #78281 (0x0x7fc95d0d1fa0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x4c) [0x7fc95d0d89bc]
/usr/lib/x86_64-linux-gnu/libuv.so.1(uv_mutex_lock+0x9) [0x7fc95c3aa689]
Mutex #1330013 (0x0x55ec3f9cf2c0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_rbtdb_create+0x497) [0x7fc95c9e5095]
Mutex #1325525 (0x0x55ec3f843f48) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(+0x411fe) [0x7fc95cb8a1fe]
mutrace: Showing 10 mutexes in order of (write) contention count:
Mutex # Changed Locked tot.Time[ms] avg.Time[ms] max.Time[ms] Cont. tot.Cont[ms] avg.Cont[ms] max.Cont[ms] Flags
1326836 959 3544 16.228 0.005 0.055 829 93.809 0.113 2.528 Mx.a-.
1332002 10563 942412 784.830 0.001 0.183 330 0.379 0.001 0.021 Mx.a-.
1329994 7845 141856 7.790 0.000 0.079 185 1.978 0.011 0.130 W!...r
(read) 989396 57.085 0.000 0.169 254 5.736 0.023 0.112 ||||||
1332378 4593 48592 1590.456 0.033 45.106 165 56.996 0.345 7.611 Wx...r
(read) 1 39.878 39.878 39.878 0 0.000 0.000 0.000 ||||||
1332379 23798 36940 37.882 0.001 0.101 108 0.210 0.002 0.081 Mx.a-.
1327168 133 314 24.442 0.078 0.276 96 8.554 0.089 0.534 Wx...r
(read) 2 1.013 0.507 0.760 0 0.000 0.000 0.000 ||||||
1325497 2107 1018717 828.111 0.001 0.207 65 0.115 0.002 0.015 Mx.a-.
78281 19 21 1.274 0.061 0.186 15 2.693 0.180 0.251 M-.--.
1330013 2650 41181 52.259 0.001 0.104 11 0.044 0.004 0.007 Wx...r
(read) 103766 96.121 0.001 0.130 8 0.099 0.012 0.049 ||||||
1325525 26482 30675 31.489 0.001 0.092 11 0.033 0.003 0.010 Mx.a-.
... ... ... ... ... ... ... ... ... ... ||||||
/|||||
Object: M = Mutex, W = RWLock, I = isc_rwlock /||||
State: x = dead, ! = inconsistent /|||
Use: R = used in realtime thread /||
Mutex Type: r = RECURSIVE, e = ERRORCHECK, a = ADAPTIVE /|
Mutex Protocol: i = INHERIT, p = PROTECT /
RWLock Kind: r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC
mutrace: Note that rwlocks are shown as two lines: write locks then read locks.
mutrace: Note that the flags column R is only valid in --track-rt mode!
mutrace: 1 condition variables used.
mutrace: No condition variable contended according to filtering parameters.
mutrace: Total runtime is 185346.476 ms.
mutrace: Results for SMP with 8 processors.
mutrace: WARNING: 139919 inconsistent mutex uses detected. Results might not be reliable.
mutrace: Fix your program first!
mutrace: WARNING: 98 internal hash collisions detected. Results might not be as reliable as they could be.
mutrace: Try to increase --hash-size=, which is currently at 400000009.
mutrace: WARNING: 533 internal mutex contention detected. Results might not be reliable as they could be.
mutrace: Try to increase --hash-size=, which is currently at 400000009.
```https://gitlab.isc.org/isc-projects/bind9/-/issues/3558Batched UPDATE processing2022-09-23T08:52:56ZTony FinchBatched UPDATE processingThere's a cool thing that can happen when you have a queue whose consumer can work in batches: as the load increases, the batch size increases, so the per-batch overhead is amortized over more queue entries and the system's overall effic...There's a cool thing that can happen when you have a queue whose consumer can work in batches: as the load increases, the batch size increases, so the per-batch overhead is amortized over more queue entries and the system's overall efficiency goes up.
This occurs in the DNS for UPDATE processing: UPDATEs are serialized, so new UPDATEs must be queued while an UPDATE is in progress. It then makes sense when an UPDATE is completed to process all pending UPDATEs in a single transaction, so the server has a chance of catching up with its backlog.Not plannedTony FinchTony Finchhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3556journal performance improvements - limit fsync()2023-04-06T17:09:34ZPetr Špačekpspacek@isc.orgjournal performance improvements - limit fsync()Version: 9.19.5-dev (Development Release) <id:b13d973>
Observation:
In a trivial test on a laptop the UPDATE performance on a single zone is about 1/300 of the query performance on the same zone. Using `tmpfs` for journal makes it as fa...Version: 9.19.5-dev (Development Release) <id:b13d973>
Observation:
In a trivial test on a laptop the UPDATE performance on a single zone is about 1/300 of the query performance on the same zone. Using `tmpfs` for journal makes it as fast as ~ 1/8 of the query performance on a 4 core machine, with multi-threading 8 virtual cores. (That kind of makes sense because of the serialization?)
From a quick look I guess it is because `fsync()` syscall is a real performance drag.
This issue is for discussing possibilities to improve UPDATE performance.
In the code I can see two relatively radical but simple opportunities for optimization:
- [ ] Make `fsync()` use for journal files configurable. IIUC `fsync()` guards only against hardware failure/kernel crash but it should not matter from perspective of a crashing process. Once the data are in kernel buffer after `write()` the process can crash but the filesystem will retain the content anyway. A fsync-knob would allow users to trade performance vs. journal resiliency against system crash (but again, not `named` crash).
- It might even make sense for for secondary zones which can be re-transferred at will.
- It is not unheard-of, see https://www.knot-dns.cz/docs/latest/singlehtml/#journal-db-mode.
- [ ] Even when `fsync()` is required/configured, I think that in `dns_journal_compact()` it should be good enough to call `fsync()` once at the very end. There should be zero risk until the new journal is renamed to the original name, so there is no need to `fsync()` it before that point. That should improve performance too.
Side-note about `fsync()`: It is a trap because on journaled filesystems it can force _all other_ transactions in filesystem journal to be flushed to disk before it even starts flushing the intended file, so it might be even slower than we would like.https://gitlab.isc.org/isc-projects/bind9/-/issues/3552Potential method to DoS the statistics channel and prevent BIND from exiting ...2023-05-23T12:31:12ZCathy AlmondPotential method to DoS the statistics channel and prevent BIND from exiting on 9.16As reported to us in [Support Ticket #21309](https://support.isc.org/Ticket/Display.html?id=21309)
The submitter writes:
This ticket is being reported against BIND 9.16.23; these issues were found during code review after the (Septembe...As reported to us in [Support Ticket #21309](https://support.isc.org/Ticket/Display.html?id=21309)
The submitter writes:
This ticket is being reported against BIND 9.16.23; these issues were found during code review after the (September) CVE announcement.
The implementation in lib/isc/httpd.c appears to be implementing the "Connection" header from HTTP/1.0 form of persistent connections. In
HTTP/1.1, persistent connections are the default. But this seems to have an effect in the lib/isc/httpd.c code only when a HTTP request has been received on the connection and the appropriate flags have been set.
isc_httpdmgr_create() accepts a timermgr argument, but appears to do nothing with it except save it into a context. There are no timeouts. So
a client can open a connection and keep it open perpetually (I've checked that this can happen). There is no quota. So if this socket is open to the public internet, a question is whether this be exploited to cause, e.g., fd exhaustion or even OOM condition. (SO_KEEPALIVE is not
set either.)
It appears that named limits the number of open accepted connections for the statistics-channel socket.
ISC BIND 9.16.23-S1's named is run with the following config:
```
options {
listen-on port 5300 { 127.0.0.1; };
// ...
};
statistics-channels {
inet * port 5302 allow { localhost; };
};
```
named logged the following message on startup:
```
21-Sep-2022 21:05:43.287 using up to 21000 sockets
```
A simple Python client program was run after setting the fd soft-limit of the client program environment:
```
$ ulimit -H -n
524288
$ ulimit -S -n 512000
$ ulimit -S -n
512000
$ cat statsconnect.py
import socket
import time
sockets = []
for i in range(0, 480000):
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.connect(('127.0.0.1', 5302))
sockets.append(s)
time.sleep(3600)
$ python statsconnect.py
^CTraceback (most recent call last):
File "/home/myself/statsconnect.py", line 7, in <module>
s.connect(('127.0.0.1', 5302))
KeyboardInterrupt
$
```
(It was interrupted by SIGINT keyboard break.)
named logged the following message upon running statsconnect.py:
```
21-Sep-2022 21:13:46.799 accept: file descriptor exceeds limit (21000/21000)
```
After that, named still responds to DNS queries:
```
$ dig +tcp +short @127.0.0.1 -p 5300 . soa
a.root-servers.net. nstld.verisign-grs.com. 2022091300 1800 900 604800 86400
$
```
But it does not accept any more connections on the statistics-channels socket (indefinitely, even after the statsconnect.py process has exited
and over 60 seconds have passed which should also factor in any wait period if the kernel automatically collects the client's fds):
```
$ telnet 127.0.0.1 5302
Trying 127.0.0.1...
telnet: connect to address 127.0.0.1: Connection timed out
$
```
So at least DoS of the statistics-channel appears possible.
And named does not terminate when attempting to stop it:
```
21-Sep-2022 21:13:46.799 accept: file descriptor exceeds limit (21000/21000)
21-Sep-2022 21:29:23.296 no longer listening on 127.0.0.1#5300
21-Sep-2022 21:29:23.298 shutting down
21-Sep-2022 21:29:23.298 stopping statistics channel on 0.0.0.0#5302
```
and blocks there indefinitely.
pstack dumps this:
```
Thread 2 (Thread 0x7fd3f1893640 (LWP 431172) "isc-net-0000"):
#0 0x00007fd3f1e627b0 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007fd3f1e5b6b2 in pthread_mutex_lock () from /lib64/libpthread.so.0
#2 0x00007fd3f245ee6f in isc_socket_cancel (sock=0x7fd3df675178, task=0x7fd3df670190, how=how@entry=15) at socket.c:4975
#3 0x00007fd3f2423f57 in isc_httpdmgr_shutdown (httpdmgrp=<optimized out>) at httpd.c:1094
#4 0x000000000044ee8c in shutdown_listener (listener=0x7fd3cdf41010) at statschannel.c:3773
#5 named_statschannels_shutdown (server=server@entry=0x7fd3df65f010) at statschannel.c:4156
#6 0x000000000043c505 in shutdown_server (task=<optimized out>, event=<optimized out>) at ./server.c:10144
#7 0x00007fd3f244c355 in task_run (task=0x7fd3df66a010) at task.c:857
#8 isc_task_run (task=0x7fd3df66a010) at task.c:950
#9 0x00007fd3f2436e49 in isc__nm_async_task (worker=0xc93790, ev0=0x7fd3df673970) at netmgr.c:879
#10 process_netievent (worker=worker@entry=0xc93790, ievent=0x7fd3df673970) at netmgr.c:958
#11 0x00007fd3f2436fc5 in process_queue (worker=worker@entry=0xc93790, type=type@entry=NETIEVENT_TASK) at netmgr.c:1027
#12 0x00007fd3f2437773 in process_all_queues (worker=0xc93790) at netmgr.c:798
#13 async_cb (handle=0xc93af0) at netmgr.c:827
#14 0x00007fd3f220fc0d in uv.async_io.part () from /lib64/libuv.so.1
#15 0x00007fd3f222ba84 in uv.io_poll.part () from /lib64/libuv.so.1
#16 0x00007fd3f2215630 in uv_run () from /lib64/libuv.so.1
#17 0x00007fd3f2437077 in nm_thread (worker0=0xc93790) at netmgr.c:733
#18 0x00007fd3f244e6d6 in isc__trampoline_run (arg=0xc7fc40) at trampoline.c:196
#19 0x00007fd3f1e592a5 in start_thread () from /lib64/libpthread.so.0
#20 0x00007fd3f1d81323 in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7fd3f1a17480 (LWP 431171) "named"):
#0 0x00007fd3f1d48ac5 in clock_nanosleep@GLIBC_2.2.5 () from /lib64/libc.so.6
#1 0x00007fd3f1d4dce7 in nanosleep () from /lib64/libc.so.6
#2 0x00007fd3f1d79669 in usleep () from /lib64/libc.so.6
#3 0x00007fd3f244cd2a in isc__taskmgr_destroy (managerp=0x47ba28 <named_g_taskmgr>) at task.c:1107
#4 0x00007fd3f242b381 in isc_managers_destroy (netmgrp=0x47ba08 <named_g_nm>, taskmgrp=0x47ba28 <named_g_taskmgr>) at managers.c:90
#5 0x000000000041772d in destroy_managers () at ./main.c:967
#6 cleanup () at ./main.c:1341
#7 main (argc=<optimized out>, argv=<optimized out>) at ./main.c:1613
```
There are 98 other threads [it is a 32 processors machine].
As the named resolver's upstream communications still use the socketmgr, could it also be impacted by this, as that 21000 is a socketmgr limit of fds?https://gitlab.isc.org/isc-projects/bind9/-/issues/3533Describe security policies on various components to the ARM2022-09-18T09:46:42ZOndřej SurýDescribe security policies on various components to the ARMWe were discussing how we should treat the security vulnerabilities in BIND 9 components and this is probably something that should go into the ARM along with recommendations.
E.g.:
* authoritative query processing (PR:N)
* recursive qu...We were discussing how we should treat the security vulnerabilities in BIND 9 components and this is probably something that should go into the ARM along with recommendations.
E.g.:
* authoritative query processing (PR:N)
* recursive query processing (PR:L)
* zone transfers
* control channel
I mean, I think we could expand and merge this document: https://gitlab.isc.org/isc-projects/bind9/-/wikis/CVSS-Scoring-Guidelines to the ARM.https://gitlab.isc.org/isc-projects/bind9/-/issues/3516Log root priming failures at severity NOTICE2024-03-27T13:34:12ZCathy AlmondLog root priming failures at severity NOTICEResolver root priming is logged at level INFO.
From BIND 9.18 and newer, root priming also logs the outcome (success or failure).
With our interest in #2744 continuing, it becomes useful to know if this condition (logged from from prim...Resolver root priming is logged at level INFO.
From BIND 9.18 and newer, root priming also logs the outcome (success or failure).
With our interest in #2744 continuing, it becomes useful to know if this condition (logged from from prime_done()) occurred because root priming failed, or because it succeeded but before we ran checkhints, the newly primed roots were no longer in cache any more (or perhaps there had been a problem writing them there?).
However, much much stuff is logged at level INFO in category Resolver and it's not uncommon for administrators to set the logging level higher for this category so that they're not overwhelmed by it.
Since logging of priming is (quite reasonably) logged at INFO because it's a routine operation, we would like to request that logging of the failure to prime, be logged at NOTICE since this exceptional.
This will also make it easier to catch this logged message on a busy resolver (for it is the busy ones that most often encounter #2744 )
See [Support ticket #20909](https://support.isc.org/Ticket/Display.html?id=20909) for an example of why we need this.https://gitlab.isc.org/isc-projects/bind9/-/issues/3509TSAN: TLS and DoH shutdown sequence2023-05-23T15:25:04ZOndřej SurýTSAN: TLS and DoH shutdown sequenceTSAN reports a warning where the underlying socket is not yet destroyed after `isc_nm_stoplistening()`, but the top socket already is.
The problem is that `isc_nm_stoplistening()` pretends to be synchronous, but it really isn't and we n...TSAN reports a warning where the underlying socket is not yet destroyed after `isc_nm_stoplistening()`, but the top socket already is.
The problem is that `isc_nm_stoplistening()` pretends to be synchronous, but it really isn't and we need to add per-thread child socket for TLS(stream) and DoH code, so we don't destroy the top socket before the underlying socket gets destroyed. Alternatively, the `isc_nm_stoplistening()` needs to take a callback and be converted to asynchronous code.
```
WARNING: ThreadSanitizer: data race (pid=7728)
Write of size 8 at 0x7b080002cbc0 by thread T11:
#0 free <null> (libtsan.so.0+0x37a28)
#1 OPENSSL_sk_free <null> (libcrypto.so.1.1+0x18156a)
#2 isc__nm_tls_cleanup_data netmgr/tlsstream.c:1122 (libisc-9.19.5-dev.so+0x8bd0d)
#3 nmsocket_cleanup netmgr/netmgr.c:729 (libisc-9.19.5-dev.so+0x252fd)
#4 nmsocket_maybe_destroy netmgr/netmgr.c:799 (libisc-9.19.5-dev.so+0x2556b)
#5 isc___nmsocket_prep_destroy netmgr/netmgr.c:861 (libisc-9.19.5-dev.so+0x256de)
#6 isc___nmsocket_detach netmgr/netmgr.c:888 (libisc-9.19.5-dev.so+0x25818)
#7 isc__nm_tls_cleanup_data netmgr/tlsstream.c:1141 (libisc-9.19.5-dev.so+0x8bb84)
#8 nmsocket_cleanup netmgr/netmgr.c:729 (libisc-9.19.5-dev.so+0x252fd)
#9 nmsocket_maybe_destroy netmgr/netmgr.c:799 (libisc-9.19.5-dev.so+0x2556b)
#10 isc___nmsocket_prep_destroy netmgr/netmgr.c:861 (libisc-9.19.5-dev.so+0x256de)
#11 tcp_close_sock netmgr/tcp.c:1209 (libisc-9.19.5-dev.so+0x29a8e)
#12 tcp_close_cb netmgr/tcp.c:1217 (libisc-9.19.5-dev.so+0x29b43)
#13 uv__finish_close /usr/src/libuv-v1.44.1/src/unix/core.c:308 (libuv.so.1+0x119b9)
#14 isc__trampoline_run /builds/isc-projects/bind9/lib/isc/trampoline.c:189 (libisc-9.19.5-dev.so+0x79d29)
Previous read of size 8 at 0x7b080002cbc0 by thread T16:
#0 memcpy <null> (libtsan.so.0+0x5da1e)
#1 OPENSSL_sk_dup <null> (libcrypto.so.1.1+0x183231)
#2 tls_readcb netmgr/tlsstream.c:606 (libisc-9.19.5-dev.so+0x89bbe)
#3 isc__nm_async_readcb netmgr/netmgr.c:2217 (libisc-9.19.5-dev.so+0x26e6b)
#4 isc__nm_readcb netmgr/netmgr.c:2190 (libisc-9.19.5-dev.so+0x2704f)
#5 isc__nm_tcp_read_cb netmgr/tcp.c:897 (libisc-9.19.5-dev.so+0x2bb8c)
#6 uv__read /usr/src/libuv-v1.44.1/src/unix/stream.c:1247 (libuv.so.1+0x22d21)
#7 isc__trampoline_run /builds/isc-projects/bind9/lib/isc/trampoline.c:189 (libisc-9.19.5-dev.so+0x79d29)
Thread T11 'isc-loop-0007' (tid=8083, running) created by main thread at:
#0 pthread_create <null> (libtsan.so.0+0x5bef5)
#1 isc_thread_create /builds/isc-projects/bind9/lib/isc/thread.c:70 (libisc-9.19.5-dev.so+0x72017)
#2 isc_loopmgr_run /builds/isc-projects/bind9/lib/isc/loop.c:467 (libisc-9.19.5-dev.so+0x596b1)
#3 run_test_doh_recv_send_POST_TLS /builds/isc-projects/bind9/tests/isc/doh_test.c:1035 (doh_test+0x40d088)
#4 cmocka_run_one_test_or_fixture <null> (libcmocka.so.0+0x5cb0)
#5 __libc_start_call_main <null> (libc.so.6+0x4043f)
Thread T16 'isc-loop-0012' (tid=8088, running) created by main thread at:
#0 pthread_create <null> (libtsan.so.0+0x5bef5)
#1 isc_thread_create /builds/isc-projects/bind9/lib/isc/thread.c:70 (libisc-9.19.5-dev.so+0x72017)
#2 isc_loopmgr_run /builds/isc-projects/bind9/lib/isc/loop.c:467 (libisc-9.19.5-dev.so+0x596b1)
#3 run_test_doh_recv_send_POST_TLS /builds/isc-projects/bind9/tests/isc/doh_test.c:1035 (doh_test+0x40d088)
#4 cmocka_run_one_test_or_fixture <null> (libcmocka.so.0+0x5cb0)
#5 __libc_start_call_main <null> (libc.so.6+0x4043f)
SUMMARY: ThreadSanitizer: data race (/lib64/libtsan.so.0+0x37a28) in free
```
and
```
WARNING: ThreadSanitizer: data race (pid=7728)
Write of size 8 at 0x7b04000055e0 by thread T11:
#0 free <null> (libtsan.so.0+0x37a28)
#1 SSL_SESSION_free <null> (libssl.so.1.1+0x3fa88)
#2 isc__nm_tls_cleanup_data netmgr/tlsstream.c:1122 (libisc-9.19.5-dev.so+0x8bd0d)
#3 nmsocket_cleanup netmgr/netmgr.c:729 (libisc-9.19.5-dev.so+0x252fd)
#4 nmsocket_maybe_destroy netmgr/netmgr.c:799 (libisc-9.19.5-dev.so+0x2556b)
#5 isc___nmsocket_prep_destroy netmgr/netmgr.c:861 (libisc-9.19.5-dev.so+0x256de)
#6 isc___nmsocket_detach netmgr/netmgr.c:888 (libisc-9.19.5-dev.so+0x25818)
#7 isc__nm_tls_cleanup_data netmgr/tlsstream.c:1141 (libisc-9.19.5-dev.so+0x8bb84)
#8 nmsocket_cleanup netmgr/netmgr.c:729 (libisc-9.19.5-dev.so+0x252fd)
#9 nmsocket_maybe_destroy netmgr/netmgr.c:799 (libisc-9.19.5-dev.so+0x2556b)
#10 isc___nmsocket_prep_destroy netmgr/netmgr.c:861 (libisc-9.19.5-dev.so+0x256de)
#11 tcp_close_sock netmgr/tcp.c:1209 (libisc-9.19.5-dev.so+0x29a8e)
#12 tcp_close_cb netmgr/tcp.c:1217 (libisc-9.19.5-dev.so+0x29b43)
#13 uv__finish_close /usr/src/libuv-v1.44.1/src/unix/core.c:308 (libuv.so.1+0x119b9)
#14 isc__trampoline_run /builds/isc-projects/bind9/lib/isc/trampoline.c:189 (libisc-9.19.5-dev.so+0x79d29)
Previous read of size 1 at 0x7b04000055e1 by thread T16:
#0 memcpy <null> (libtsan.so.0+0x5da1e)
#1 ssl_session_dup <null> (libssl.so.1.1+0x3fd8f)
#2 tls_readcb netmgr/tlsstream.c:606 (libisc-9.19.5-dev.so+0x89bbe)
#3 isc__nm_async_readcb netmgr/netmgr.c:2217 (libisc-9.19.5-dev.so+0x26e6b)
#4 isc__nm_readcb netmgr/netmgr.c:2190 (libisc-9.19.5-dev.so+0x2704f)
#5 isc__nm_tcp_read_cb netmgr/tcp.c:897 (libisc-9.19.5-dev.so+0x2bb8c)
#6 uv__read /usr/src/libuv-v1.44.1/src/unix/stream.c:1247 (libuv.so.1+0x22d21)
#7 isc__trampoline_run /builds/isc-projects/bind9/lib/isc/trampoline.c:189 (libisc-9.19.5-dev.so+0x79d29)
Thread T11 'isc-loop-0007' (tid=8083, running) created by main thread at:
#0 pthread_create <null> (libtsan.so.0+0x5bef5)
#1 isc_thread_create /builds/isc-projects/bind9/lib/isc/thread.c:70 (libisc-9.19.5-dev.so+0x72017)
#2 isc_loopmgr_run /builds/isc-projects/bind9/lib/isc/loop.c:467 (libisc-9.19.5-dev.so+0x596b1)
#3 run_test_doh_recv_send_POST_TLS /builds/isc-projects/bind9/tests/isc/doh_test.c:1035 (doh_test+0x40d088)
#4 cmocka_run_one_test_or_fixture <null> (libcmocka.so.0+0x5cb0)
#5 __libc_start_call_main <null> (libc.so.6+0x4043f)
Thread T16 'isc-loop-0012' (tid=8088, running) created by main thread at:
#0 pthread_create <null> (libtsan.so.0+0x5bef5)
#1 isc_thread_create /builds/isc-projects/bind9/lib/isc/thread.c:70 (libisc-9.19.5-dev.so+0x72017)
#2 isc_loopmgr_run /builds/isc-projects/bind9/lib/isc/loop.c:467 (libisc-9.19.5-dev.so+0x596b1)
#3 run_test_doh_recv_send_POST_TLS /builds/isc-projects/bind9/tests/isc/doh_test.c:1035 (doh_test+0x40d088)
#4 cmocka_run_one_test_or_fixture <null> (libcmocka.so.0+0x5cb0)
#5 __libc_start_call_main <null> (libc.so.6+0x4043f)
SUMMARY: ThreadSanitizer: data race (/lib64/libtsan.so.0+0x37a28) in free
```
This issue also affects 9.18, but is more prominent in 9.19 loopmgr code.Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3502xfer-in error failed while receiving responses: not exact2022-08-24T13:33:38ZJan Sorensenxfer-in error failed while receiving responses: not exact### Description
I have upgraded my secondary DNS server from 9.18.5 to 9.18.6. The primary is 9.18.5.
As a result I now receive a couple of error messages:
xfer-in: error: transfer of (various domains from master) failed while receiving ...### Description
I have upgraded my secondary DNS server from 9.18.5 to 9.18.6. The primary is 9.18.5.
As a result I now receive a couple of error messages:
xfer-in: error: transfer of (various domains from master) failed while receiving responses: not exact
A singe non-DNSSEC domain does not generate the error.
### Request
A more useful error message.
### Links / referencesNot plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3497CID 356081 356083 396973 396970: High impact quality (Y2K38_SAFETY)2022-08-18T07:04:24ZMichal NowakCID 356081 356083 396973 396970: High impact quality (Y2K38_SAFETY)Update Coverity Scan reported the following year 2038 issues:
```
*** CID 356083: High impact quality (Y2K38_SAFETY)
/bin/dnssec/dnssec-keygen.c: 775 in keygen()
769 if (ctx->setttl) {
770 dst_key_setttl(key, ctx->ttl);
7...Update Coverity Scan reported the following year 2038 issues:
```
*** CID 356083: High impact quality (Y2K38_SAFETY)
/bin/dnssec/dnssec-keygen.c: 775 in keygen()
769 if (ctx->setttl) {
770 dst_key_setttl(key, ctx->ttl);
771 }
772
773 /* Set dnssec-policy related metadata */
774 if (ctx->policy != NULL) {
>>> CID 356083: High impact quality (Y2K38_SAFETY)
>>> A "time_t" value is stored in an integer with too few bits to accommodate it. The expression "ctx->lifetime" is cast to "uint32_t".
775 dst_key_setnum(key, DST_NUM_LIFETIME, ctx->lifetime);
776 dst_key_setbool(key, DST_BOOL_KSK, ctx->ksk);
777 dst_key_setbool(key, DST_BOOL_ZSK, ctx->zsk);
778 }
779
780 /*
```
---
```
*** CID 356081: High impact quality (Y2K38_SAFETY)
/lib/isc/time.c: 401 in isc_time_parsehttptimestamp()
395 return (ISC_R_UNEXPECTED);
396 }
397 when = isc_tm_timegm(&t_tm);
398 if (when == -1) {
399 return (ISC_R_UNEXPECTED);
400 }
>>> CID 356081: High impact quality (Y2K38_SAFETY)
>>> A "time_t" value is stored in an integer with too few bits to accommodate it. The expression "when" is cast to "unsigned int".
401 isc_time_set(t, when, 0);
402 return (ISC_R_SUCCESS);
403 }
404
405 void
406 isc_time_formatISO8601L(const isc_time_t *t, char *buf, unsigned int len) {
```
Also in `lib/isc/unix/time.c` on ~"v9.16".
---
~"v9.16"-only and ~Low:
```
*** CID 396973: High impact quality (Y2K38_SAFETY)
/lib/dns/tests/update_test.c: 77 in set_mystdtime()
71 struct tm tm;
72
73 memset(&tm, 0, sizeof(tm));
74 tm.tm_year = year - 1900;
75 tm.tm_mon = month - 1;
76 tm.tm_mday = day;
>>> CID 396973: High impact quality (Y2K38_SAFETY)
>>> A "time_t" value is stored in an integer with too few bits to accommodate it. The expression "timegm(&tm)" is cast to "uint32_t".
77 mystdtime = timegm(&tm);
78 }
79
80 /*
81 * Override isc_stdtime_get() from lib/isc/[unix/win32]/stdtime.c
82 * with our own for testing purposes.
```
```
*** CID 396970: High impact quality (Y2K38_SAFETY)
/bin/tests/optional/gsstest.c: 360 in initctx1()
354 c = scanf("%511s", gssid);
355 if (c == EOF) {
356 return;
357 }
358
359 snprintf(contextname, sizeof(contextname), "gsstest.context.%d.",
>>> CID 396970: High impact quality (Y2K38_SAFETY)
>>> A "time_t" value is stored in an integer with too few bits to accommodate it. The expression "time(NULL)" is cast to "int".
360 (int)time(NULL));
361
362 printf("Initctx - context name we're using: %s\n", contextname);
363
364 printf("Negotiating GSSAPI context: ");
365 printf("%s", gssid);
```Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3495Suspected false positive in shutdown system test2023-11-06T11:20:37ZMark AndrewsSuspected false positive in shutdown system testJob [#2699254](https://gitlab.isc.org/isc-projects/bind9/-/jobs/2699254) failed for 39a8f70bd5c260aa4ad5a7dd1e015597c9ec7d78:
```
S:shutdown:2022-08-17T01:26:40+0000
8099T:shutdown:1:A
8100A:shutdown:System test shutdown
8101I:shutdown:P...Job [#2699254](https://gitlab.isc.org/isc-projects/bind9/-/jobs/2699254) failed for 39a8f70bd5c260aa4ad5a7dd1e015597c9ec7d78:
```
S:shutdown:2022-08-17T01:26:40+0000
8099T:shutdown:1:A
8100A:shutdown:System test shutdown
8101I:shutdown:PORTS:8938,8939,8940,8941,8942,8943,8944,8945,8946,8947,8948,8949,8950
8102I:shutdown:starting servers
8103D:shutdown:============================= test session starts ==============================
8104D:shutdown:platform linux -- Python 3.6.8, pytest-3.4.2, py-1.5.3, pluggy-0.6.0 -- /usr/libexec/platform-python
8105D:shutdown:rootdir: /builds/isc-projects/bind9/bin/tests/system/shutdown, inifile:
8106D:shutdown:plugins: hypothesis-3.44.24
8107D:shutdown:collecting ... collected 1 item
8108D:shutdown:
8109D:shutdown:tests-shutdown.py::test_named_shutdown FAILED [100%]
8110D:shutdown:
8111D:shutdown:=================================== FAILURES ===================================
8112D:shutdown:_____________________________ test_named_shutdown ______________________________
8113D:shutdown:
8114D:shutdown:named_port = 8938, control_port = 8950
8115D:shutdown:
8116D:shutdown: def test_named_shutdown(named_port, control_port):
8117D:shutdown: # pylint: disable-msg=too-many-locals
8118D:shutdown: cfg_dir = os.path.join(os.getcwd(), "resolver")
8119D:shutdown: assert os.path.isdir(cfg_dir)
8120D:shutdown:
8121D:shutdown: cfg_file = os.path.join(cfg_dir, "named.conf")
8122D:shutdown: assert os.path.isfile(cfg_file)
8123D:shutdown:
8124D:shutdown: named = os.getenv("NAMED")
8125D:shutdown: assert named is not None
8126D:shutdown:
8127D:shutdown: rndc = os.getenv("RNDC")
8128D:shutdown: assert rndc is not None
8129D:shutdown:
8130D:shutdown: # rndc configuration resides in ../common/rndc.conf
8131D:shutdown: rndc_cfg = os.path.join("..", "common", "rndc.conf")
8132D:shutdown: assert os.path.isfile(rndc_cfg)
8133D:shutdown:
8134D:shutdown: # rndc command with default arguments.
8135D:shutdown: rndc_cmd = [rndc, "-c", rndc_cfg, "-p", str(control_port), "-s", "10.53.0.3"]
8136D:shutdown:
8137D:shutdown: # We create a resolver instance that will be used to send queries.
8138D:shutdown: resolver = dns.resolver.Resolver()
8139D:shutdown: resolver.nameservers = ["10.53.0.3"]
8140D:shutdown: resolver.port = named_port
8141D:shutdown:
8142D:shutdown: # We test named shutting down using two methods:
8143D:shutdown: # Method 1: using rndc ctop
8144D:shutdown: # Method 2: killing with SIGTERM
8145D:shutdown: # In both methods named should exit gracefully.
8146D:shutdown: for kill_method in ("rndc", "sigterm"):
8147D:shutdown: named_cmdline = [named, "-c", cfg_file, "-f"]
8148D:shutdown: with subprocess.Popen(named_cmdline, cwd=cfg_dir) as named_proc:
8149D:shutdown: # Ensure named is running
8150D:shutdown: assert named_proc.poll() is None
8151D:shutdown: # wait for named to finish loading
8152D:shutdown: for _ in range(10):
8153D:shutdown: try:
8154D:shutdown: resolver.query("version.bind", "TXT", "CH")
8155D:shutdown: break
8156D:shutdown: except (dns.resolver.NoNameservers, dns.exception.Timeout):
8157D:shutdown: time.sleep(1)
8158D:shutdown:
8159D:shutdown: do_work(
8160D:shutdown:> named_proc, resolver, rndc_cmd, kill_method, n_workers=12, n_queries=16
8161D:shutdown: )
8162D:shutdown:
8163D:shutdown:tests-shutdown.py:179:
8164D:shutdown:_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
8165D:shutdown:tests-shutdown.py:114: in do_work
8166D:shutdown: result = future.result()
8167D:shutdown:/usr/lib64/python3.6/concurrent/futures/_base.py:425: in result
8168D:shutdown: return self.__get_result()
8169D:shutdown:/usr/lib64/python3.6/concurrent/futures/_base.py:384: in __get_result
8170D:shutdown: raise self._exception
8171D:shutdown:/usr/lib64/python3.6/concurrent/futures/thread.py:56: in run
8172D:shutdown: result = self.fn(*self.args, **self.kwargs)
8173D:shutdown:/usr/lib/python3.6/site-packages/dns/resolver.py:962: in query
8174D:shutdown: source_port=source_port)
8175D:shutdown:/usr/lib/python3.6/site-packages/dns/query.py:257: in udp
8176D:shutdown: one_rr_per_rrset=one_rr_per_rrset)
8177D:shutdown:/usr/lib/python3.6/site-packages/dns/message.py:807: in from_wire
8178D:shutdown: reader.read()
8179D:shutdown:/usr/lib/python3.6/site-packages/dns/message.py:746: in read
8180D:shutdown: self._get_section(self.message.answer, ancount)
8181D:shutdown:/usr/lib/python3.6/site-packages/dns/message.py:720: in _get_section
8182D:shutdown: self.message.origin)
8183D:shutdown:/usr/lib/python3.6/site-packages/dns/rdata.py:457: in from_wire
8184D:shutdown: cls = get_rdata_class(rdclass, rdtype)
8185D:shutdown:/usr/lib/python3.6/site-packages/dns/rdata.py:368: in get_rdata_class
8186D:shutdown: rdclass_text, rdtype_text]))
8187D:shutdown:_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
8188D:shutdown:
8189D:shutdown:name = 'dns.rdtypes.IN.A'
8190D:shutdown:
8191D:shutdown: def import_module(name):
8192D:shutdown: mod = __import__(name)
8193D:shutdown: components = name.split('.')
8194D:shutdown: for comp in components[1:]:
8195D:shutdown:> mod = getattr(mod, comp)
8196D:shutdown:E AttributeError: module 'dns.rdtypes' has no attribute 'IN'
8197D:shutdown:
8198D:shutdown:/usr/lib/python3.6/site-packages/dns/rdata.py:356: AttributeError
8199D:shutdown:----------------------------- Captured stderr call -----------------------------
8200D:shutdown:lt-rndc: recv failed: connection reset
8201D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8202D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8203D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8204D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8205D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8206D:shutdown:lt-rndc: connect failed: 10.53.0.3#8950: connection refused
8207D:shutdown:========================== 1 failed in 32.26 seconds ===========================
8208I:system:FAILED
```Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3490ARM-9.18.5: Debug-Level for the example regarding "query-errors" is not corre...2022-08-16T12:37:09ZThomas AmgartenARM-9.18.5: Debug-Level for the example regarding "query-errors" is not correct documented<!--
If the bug you are reporting is potentially security-related - for example,
if it involves an assertion failure or other crash in `named` that can be
triggered repeatedly - then please do *NOT* report it here, but send an
email to [...<!--
If the bug you are reporting is potentially security-related - for example,
if it involves an assertion failure or other crash in `named` that can be
triggered repeatedly - then please do *NOT* report it here, but send an
email to [security-officer@isc.org](security-officer@isc.org).
-->
### Summary
Regarding the current ARM (9.18.5) on page 102 (explanation about the 'The query-errors Category'), the message "fetch completed at resolver.c:..." about the detailed context information which results in ```SERVFAIL``` should be logged in ```debug``` level 2 or higher, but in reality, this message will only be logged with ```debug``` level 4 or higher. See the corresponding output with ```debug``` level 4 in BIND-9.18.5 below:
```
12-Aug-2022 08:47:08.225 query-errors: debug 4: fetch completed at resolver.c:5607 for dnssec-failed.org/A in 1.204014: broken trust chain/broken trust chain [domain:dnssec-failed.org,referral:1,restart:2,qrysent:1,timeout:0,lame:0,quota:0,neterr:0,badresp:0,adberr:0,findfail:0,valfail:1
```
### BIND version used
9.18.5
### Steps to reproduce
* Enable query-errors logging with level 2
```
logging {
channel query-errors {
file "/var/log/named/named.log";
severity debug 2;
print-severity yes;
print-time yes;
print-category yes;
category query-errors { query-errors; };
};
```
* ```dig``` for ```dnssec-failed.org``` and check the output for the detailed information. In ```severity debug 2;```, the log contains only the following message **and not** the detailed information:
```
12-Aug-2022 08:57:30.971 query-errors: debug 1: client @0x7f8960a0a168 192.168.236.2#58015 (dnssec-failed.org): query failed (broken trust chain) for dnssec-failed.org/IN/A at query.c:7722
```
### What is the current *bug* behavior?
Debug level information is wrong in the ARM.
### What is the expected *correct* behavior?
The correct debug level like this:
_At ```debug``` level 4 or higher, detailed context information about recursive resolutions that resulted in SERVFAIL is logged.
The log message looks like this:_
```
...
...
```
### Relevant configuration filesNot plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3482Clarify ACLs and their interaction in the ARM2022-10-06T10:22:09ZPetr Špačekpspacek@isc.orgClarify ACLs and their interaction in the ARMThings I noticed in the ARM which I think are in need of clarification:
- allow-query*/allow-recursion* descriptions are just confusing.
- Sections [8.1.4. Address Match Lists](https://bind9.readthedocs.io/en/v9_19_3/reference.html#addr...Things I noticed in the ARM which I think are in need of clarification:
- allow-query*/allow-recursion* descriptions are just confusing.
- Sections [8.1.4. Address Match Lists](https://bind9.readthedocs.io/en/v9_19_3/reference.html#address-match-lists) and [7.1. Access Control Lists](https://bind9.readthedocs.io/en/v9_19_3/chapter7.html#access-control-lists) overlap and really should be merged
## Summary how I believe ACLs work
**Proceed with caution!**
Different sets of ACLs affect different queries, depending on whether the server has data in cache or if the data are in an authoritative zone on the server. Caveats:
- `type mirror` zone still counts as cache (cache ACLs apply, I think)
- `type static-stub` zones are not queriable without recursion desired bit anyway
With this in mind, I _believe_ BIND checks this:
- blackhole acl checks client address and drops packets on the floor - highest priority
- for queries into authoritative zones check ONLY:
- allow-query
- allow-query-on
- for queries into cache
- for data present in the cache check:
- recursion (yes, even if no recursion is happening yet)
- allow-query-cache
- allow-query-cache-on
- _(no allow-query(-on) ACL here!)_
- for data NOT present in the cache **additionally** check (before a fetch is started):
- allow-recursion
- allow-recursion-on
- I.e. a query which triggers a fetch from elsewhere must match all the allow-query-cache(-on) and allow-recursion(-on)
Fun fact: Data stay in cache even if `recursion yes;` is changed to `recursion no;`. Subsequent `rndc reconfig` will create configuration with data in cache but without any means to access it. Turning it back on will provide access to the old cache content.
## Text problems/suggestions
- allow-query-cache(-on) does not "effectively control recursion". It control access to cache data WITHOUT doing recursion: I.e. queries allowed by these ACLs can get content of the cache but not necessarily trigger recursion for things which are missing in the cache. (equivalent of `dig +norecurse` queries)
- allow-recursion(-on) control what queries do trigger recursion for data not available in cache
- allow-query - also covers updates (must intersect with allow-update?)
Relevant log message:
```
update 'example.com/IN' denied due to allow-query
```
(Implementation wise it makes sense because of prerequisites in the update messages, but it is not mentioned in the ARM. Basically it is impossible to make write-only client - no big deal, but better to mention that the ACLs must intersect.)https://gitlab.isc.org/isc-projects/bind9/-/issues/3480unsupported optional libraries2022-08-05T11:42:43ZPeter Daviesunsupported optional librariesBased on the experiences of a user that experienced problems compiling the
BIND man pages with an older version of Sphinx.
There are a number of optional libraries that BIND can be compiled with and it
isn't always clear which v...Based on the experiences of a user that experienced problems compiling the
BIND man pages with an older version of Sphinx.
There are a number of optional libraries that BIND can be compiled with and it
isn't always clear which versions current BIND releases support.
In so far as the configure script doesn't check the versions of these we might
want to consider adding a note to the ARM, if one does not already exist.
I found the following:
sphinx, json-c, zlib, lmdb, libmaxminddb, libfstrm, libprotobuf-c, libidn2,
readline, libedit
There may be morehttps://gitlab.isc.org/isc-projects/bind9/-/issues/3472IPv4-only mode not respected for zone transfers2024-02-24T07:55:11ZThomas AmgartenIPv4-only mode not respected for zone transfers### Summary
Running BIND in IPv4-only-mode (```named -4```) and using a mirror zone (local root), then BIND tries to AXFR the root zone with IPv6 and reports failures about the unreachability:
```
27-Jul-2022 08:57:43.309 general: info:...### Summary
Running BIND in IPv4-only-mode (```named -4```) and using a mirror zone (local root), then BIND tries to AXFR the root zone with IPv6 and reports failures about the unreachability:
```
27-Jul-2022 08:57:43.309 general: info: zone ./IN: refresh: failure trying primary 2001:500:2::c#53 (source ::#0): operation canceled
27-Jul-2022 08:57:43.309 general: info: zone ./IN: refresh: failure trying primary 2001:500:2f::f#53 (source ::#0): operation canceled
27-Jul-2022 08:57:43.809 general: info: zone ./IN: refresh: failure trying primary 2001:500:12::d0d#53 (source ::#0): operation canceled
27-Jul-2022 08:57:43.809 general: info: zone ./IN: refresh: failure trying primary 2001:7fd::1#53 (source ::#0): operation canceled
27-Jul-2022 08:57:44.309 general: info: zone ./IN: refresh: failure trying primary 2620:0:2830:202::132#53 (source ::#0): operation canceled
27-Jul-2022 08:57:44.309 general: info: zone ./IN: refresh: failure trying primary 2620:0:2d0:202::132#53 (source ::#0): operation canceled
```
### BIND version used
```
$ named -V
BIND 9.18.5 (Stable Release) <id:6593103>
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.5' '--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' 'PKG_CONFIG_PATH=:/usr/local/libuv/lib/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 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
threads support is enabled
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
Create a mirror zone:
```
zone "." {
type mirror;
notify no;
};
```
Run BIND with IPv4-only:
```
$ /usr/local/bind/sbin/named -4 -t /opt/chroot/bind -u named -c /etc/named/named.conf
```
And now check the log for the IPv6 failure:
```
27-Jul-2022 09:18:59.148 general: info: zone ./IN: refresh: failure trying primary 2001:500:200::b#53 (source ::#0): operation canceled
27-Jul-2022 09:18:59.651 general: info: zone ./IN: refresh: failure trying primary 2001:500:2::c#53 (source ::#0): operation canceled
27-Jul-2022 09:18:59.651 general: info: zone ./IN: refresh: failure trying primary 2001:500:2f::f#53 (source ::#0): operation canceled
27-Jul-2022 09:19:00.151 general: info: zone ./IN: refresh: failure trying primary 2001:500:12::d0d#53 (source ::#0): operation canceled
27-Jul-2022 09:19:00.151 general: info: zone ./IN: refresh: failure trying primary 2001:7fd::1#53 (source ::#0): operation canceled
27-Jul-2022 09:19:00.651 general: info: zone ./IN: refresh: failure trying primary 2620:0:2830:202::132#53 (source ::#0): operation canceled
27-Jul-2022 09:19:00.651 general: info: zone ./IN: refresh: failure trying primary 2620:0:2d0:202::132#53 (source ::#0): operation canceled
```
### What is the current *bug* behavior?
BIND tries to AXFR the root zone over IPv6, although ```named``` is configured to run in IPv4-only-mode.
### What is the expected *correct* behavior?
Not trying to AXFR the mirror zone over IPv6.
### Relevant configuration files
### Relevant logs and/or screenshots
Failure in the log:
```
27-Jul-2022 09:11:18.990 general: info: zone ./IN: refresh: failure trying primary 2001:500:2::c#53 (source ::#0): operation canceled
27-Jul-2022 09:11:18.990 general: info: zone ./IN: refresh: failure trying primary 2001:500:2f::f#53 (source ::#0): operation canceled
27-Jul-2022 09:11:19.490 general: info: zone ./IN: refresh: failure trying primary 2001:500:12::d0d#53 (source ::#0): operation canceled
27-Jul-2022 09:11:19.490 general: info: zone ./IN: refresh: failure trying primary 2001:7fd::1#53 (source ::#0): operation canceled
27-Jul-2022 09:11:19.990 general: info: zone ./IN: refresh: failure trying primary 2620:0:2830:202::132#53 (source ::#0): operation canceled
27-Jul-2022 09:11:19.990 general: info: zone ./IN: refresh: failure trying primary 2620:0:2d0:202::132#53 (source ::#0): operation canceled
```
### Possible fixesMay 2024 (9.18.27, 9.18.27-S1, 9.19.24)Mark AndrewsMark Andrewshttps://gitlab.isc.org/isc-projects/bind9/-/issues/3470Implement RESINFO type2022-07-26T21:55:40ZMark AndrewsImplement RESINFO typehttps://datatracker.ietf.org/doc/html/draft-reddy-add-resolver-info-05
The draft still needs work and I've recommended that *ws be treated as
zero length ws when encoding to wire.
A type code has yet to be assigned.
We should also rej...https://datatracker.ietf.org/doc/html/draft-reddy-add-resolver-info-05
The draft still needs work and I've recommended that *ws be treated as
zero length ws when encoding to wire.
A type code has yet to be assigned.
We should also reject invalid json when parsing the master file.https://gitlab.isc.org/isc-projects/bind9/-/issues/3465validator repeatedly checks insecurity proofs for insecure domains2022-09-06T13:14:35ZPetr Špačekpspacek@isc.orgvalidator repeatedly checks insecurity proofs for insecure domains<!--
If the bug you are reporting is potentially security-related - for example,
if it involves an assertion failure or other crash in `named` that can be
triggered repeatedly - then please do *NOT* report it here, but send an
email to [...<!--
If the bug you are reporting is potentially security-related - for example,
if it involves an assertion failure or other crash in `named` that can be
triggered repeatedly - then please do *NOT* report it here, but send an
email to [security-officer@isc.org](security-officer@isc.org).
-->
### Summary
It seems that DNSSEC validator rechecks insecurity proofs several times while processing answer from an insecure domain.
### BIND version used
- main: 2c3eea19173bacc496d3b82a94e4b43fd067f2c4
### Steps to reproduce
- Increase logging for validator. I've used this patch: [log.patch](/uploads/e647ce5846c8c9218ecf5ef53cd5fefb/log.patch)
- Query for a subdomain of an insecure domain: `dig a.b.c.d.e.f.google.com`
- Query for another subdomain: `dig 0.b.c.d.e.f.google.com`
- Check logs
### What is the current *bug* behavior?
```
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: starting
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: attempting negative response validation from message
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: validate_neg_rrset: creating validator for google.com SOA
20-Jul-2022 16:20:23.334 validating google.com/SOA: starting
20-Jul-2022 16:20:23.334 validating google.com/SOA: attempting insecurity proof
20-Jul-2022 16:20:23.334 validating google.com/SOA: checking existence of DS at 'com'
20-Jul-2022 16:20:23.334 validating google.com/SOA: checking existence of DS at 'google.com'
20-Jul-2022 16:20:23.334 validating google.com/SOA: marking as answer (proveunsecure (4))
20-Jul-2022 16:20:23.334 validator @0x7f1c4d264400: dns_validator_destroy
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: in validator_callback_nsec
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: resuming validate_nx
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: nonexistence proof(s) not found
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: checking existence of DS at 'com'
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: checking existence of DS at 'google.com'
20-Jul-2022 16:20:23.334 validating _.f.google.com/A: marking as answer (proveunsecure (4))
20-Jul-2022 16:20:23.334 validator @0x7f1c4d263a00: dns_validator_destroy
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: starting
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: attempting negative response validation from message
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: validate_neg_rrset: creating validator for google.com SOA
20-Jul-2022 16:20:23.371 validating google.com/SOA: starting
20-Jul-2022 16:20:23.371 validating google.com/SOA: attempting insecurity proof
20-Jul-2022 16:20:23.371 validating google.com/SOA: checking existence of DS at 'com'
20-Jul-2022 16:20:23.371 validating google.com/SOA: checking existence of DS at 'google.com'
20-Jul-2022 16:20:23.371 validating google.com/SOA: marking as answer (proveunsecure (4))
20-Jul-2022 16:20:23.371 validator @0x7f1c4d264400: dns_validator_destroy
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: in validator_callback_nsec
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: resuming validate_nx
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: nonexistence proof(s) not found
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: checking existence of DS at 'com'
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: checking existence of DS at 'google.com'
20-Jul-2022 16:20:23.371 validating 0.b.c.d.e.f.google.com/A: marking as answer (proveunsecure (4))
20-Jul-2022 16:20:23.371 validator @0x7f1c4d263000: dns_validator_destroy
```
This is probably related to fact that validation proceeds "down" even if parent zone is proved to be insecure. This can be seen e.g. on `dualstack.osff2.map.fastly.net A` query. I would expect it to stop doing things at `fastly.net DS` level.
### What is the expected *correct* behavior?
I would expect the validation to be cut soon on `checking existence of DS at 'com'`. In the log excerpt for google.com subdomains it repeats three times, along with insecurity proofs for domains we should be marked as insecure in cache (`b.c.d.e.f.google.com` and everything up to `google.com`.)
### Relevant configuration files
Default config.Not plannedhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3464Histograms for timing and memory statistics2023-11-02T17:05:05ZTony FinchHistograms for timing and memory statisticsBIND needs to be able to record statistics covering a wide range of possible values (several decimal orders of magnitude):
* latency times, from submilliseond queries on the same LAN to multi-minute zone transfers
* memory usage, fo...BIND needs to be able to record statistics covering a wide range of possible values (several decimal orders of magnitude):
* latency times, from submilliseond queries on the same LAN to multi-minute zone transfers
* memory usage, for zones from a handful of records to tens of millions
* message sizes, from 64 bytes to 64 kilobytes
In this issue I'm outlining a possible design for a general-purpose histogram data structure,
that could be added to `libisc` for collecting statistics efficiently in several places in BIND.
## existing histograms in BIND
The statistics channel has histograms for request and response sizes, which use buckets that
are defined manually with some tediously repetitive code. These could be replaced by the
proposed self-tuning histograms, although the bucketing will be somewhat different.
## examples of general-purpose histograms
It's possible to record histograms of values covering a wide range, with bucket sizes chosen automatically to provide a particular level of accuracy (e.g. 1% or 10%), and without using more than a few KiB for each histogram. Existing examples are:
* [circllhist, Circonus log-linear histogram](https://github.com/openhistogram/libcircllhist),
aka [OpenHistogram](https://openhistogram.io/)
Uses decimal floating point with two digits of mantissa and a 1 byte exponent,
to record values with 1% accuracy.
* [DDSketch from DataDog](https://www.datadoghq.com/blog/engineering/computing-accurate-percentiles-with-ddsketch/)
Uses the floating-point logarithm to a base derived from the required accuracy, rounded to an integer to make a bucket index.
Has an alternative "fast" mode more like HdrHistogram.
* [HdrHistogram, high dynamic range histogram](http://www.hdrhistogram.org/)
Uses low-precision floating point numbers as bucket indexes.
* [hg64, 64-bit histograms](https://github.com/fanf2/hg64)
My prototype implementation intended for use in BIND.
The DataDog blog article has a nice overview, and compares a quantile sketch implementation (that is designed for a particular rank error) with a histogram (designed for a particular value error). From my reading on this topic I concluded that histograms are both easier to understand, simpler to implement, and have similar or better CPU and memory usage compared to rank-error-based quantile sketches.
## key idea
The histogram counts how many measurements (time or space) have particular `uint64_t` value
or range of values, according to the histogram's configured precision (e.g. 1% or 10%).
Each range of values corresponds to a bucket or counter.
My prototype `hg64` uses a log-linear bucket spacing, which has two parts:
* a logarithm of the value to cover a large dynamic range with a few bits;
specifically, the log base 2 of a `uint64_t` varies from 0 to 63, which fits in 6 bits.
* linear, evenly spaced buckets between logarithms, to provide more precision
than you can get from just a power of 2 or 10. 4 buckets per log are enough
for 10% precision; 32 buckets per log gives 1% precision.
This log-linear bucketing is the same thing as decimal scientific notation,
like 1e9 (1 significant digit, 10% precision) or 2.2e8 (2 significant digits, 1% precision).
It's also the same as a (low-precision) binary floating point number:
the FP exponent is the logarithmic part, and the FP mantissa is the linear part.
## measurements and values
When counting time measurements, it makes sense for the `uint64_t` value to be the time measured in nanoseconds. This allows the histogram to count any time measurements we are likely to need, from submicrosecond up to a few centuries. There is no point using lower-precision time measurements because the histogram bucketing algorithm will reduce the precision as required.
Unlike nanosecond measurements, whose values are towards the logarithmic mid-range of `uint64_t`, memory measurements tend to cluster around zero. The `hg64` bucketing algorithm provides one counter for each distinct small integer; for instance, with 1% precision `hg64` has a counter for each value from 0 to 63, above which multiple values share each counter. To make the best use of these small-value counters, it makes sense to divide a memory measurement to get the desired resolution. For example, if the allocator quantum is 16 bytes, divide an allocation size by 16 before using it as a histogram value.
## incrementing counters quickly
It is very cheap to turn a `uint64_t` value into a bucket number, using CLZ to get the logarithm
with some bit shuffling to move things into place. The basic principle is
roughly the same as used by HdrHistogram and fast-mode DDSketch.
[Paul Khuong encouraged me to use his algorithm](https://twitter.com/pkhuong/status/1571831293335277573)
which is smaller and faster than the version I developed for my proof-of-concept.
As in BIND's existing statistics code, we use a relaxed atomic increment to update a counter.
When the histogram is in cache and uncontended, the whole operation (calculating the bucket
number and incrementing the counter) takes less than 2.5ns in my prototype code.
## efficient storage
The `hg64` bucket keys are small, e.g. 8 bits for 10% precision, or 11 bits for 1% precision.
We could store the buckets as a simple array of counters, which would use 2 KiB for 10%
precision, or 16 KiB for 1% precision. However a large fraction of that space will be
unused, because the values we are recording do not cover anywhere near 20 orders of
magnitude.
My prototype code has a 64 entry top-level array (one for each possible exponent)
and allocate each sub-array on demand (with a counter for each possible mantissa).
Most of the sub-arrays will remain unused. This layout supports lock-free multithreading.
## operations on histograms
* given a value, find its rank (or percentile)
* find the value at a given rank (or percentile)
* get the mean and standard deviation of the data recorded in the histogram
* merge two histograms (which may differ in precision)
* dump and load a histogram in text (e.g. csv, xml, json) and/or binary (for efficiency)
* export a histogram to a user-selected collection of buckets (e.g. for prometheus)
I have implementations of the first four.
The rank and percentile queries work on a snapshot of the working histogram, to avoid multithreading races and to make the calculations more efficient.
## exporting data
An important consumer for data recorded in histograms is Prometheus.
The docs <https://prometheus.io/docs/practices/histograms/> say it supports
* a "histogram" type (actually a cumulative frequency digest) where quantiles are calculated on the server
* a "summary" type, where quantiles are calculated on the client and the server aggregates them over a sliding window
Prometheus has its own textual format for exposing / ingesting data,
<https://prometheus.io/docs/instrumenting/exposition_formats/>.
It looks like it would be fairly easy for `hg64` and BIND to support it,
though it isn't clear whether the server is able to re-bucket data that
is exposed with a different bucketing than configured on the server.
## elsewhere on gitlab
Related issues #598 #2101 #3455Not plannedTony FinchTony Finchhttps://gitlab.isc.org/isc-projects/bind9/-/issues/3457Update BIND's catalog zones implementation to the latest draft (draft-ietf-dn...2023-03-28T08:52:32ZArаm SаrgsyаnUpdate BIND's catalog zones implementation to the latest draft (draft-ietf-dnsop-dns-catalog-zones-09)DNS Catalog Zones internet-draft document has been recently updated to draft version 9 (https://datatracker.ietf.org/doc/html/draft-ietf-dnsop-dns-catalog-zones-09).DNS Catalog Zones internet-draft document has been recently updated to draft version 9 (https://datatracker.ietf.org/doc/html/draft-ietf-dnsop-dns-catalog-zones-09).Not plannedArаm SаrgsyаnArаm Sаrgsyаn