Hello Mark & List,Thank you for responding, I'm running bind-9.18.26-1.fc40.x86_64 and using nsupdate 9.16.27-Debian to send the updates, using rndc Version: 9.18.26.
I'm issuing commands through rndc to set the trace level to 99 -> "rndc trace 99". rndc seems to work correctly in all other commands I've employed.
My question is limited to the proper method for turning on the debugging logs for the "update" section of the code.
My specific question is: Will or should this turn on more verbose logs for the update section of the code.
I'm quite willing to find my own errors in the configuration. Getting the verbose logs to provide more than just "REFUSED" would be most helpful and save a gdb session.
I'm not a paying customer and not expecting detailed help from ISC, only wondering if the "rndc trace 99" should have activated the more verbose logs.
Please pardon the reference to Fedora.My configuration files have significant private, related, information beyond the keys, and I would rather not post them here. I'm willing to send them directly if you would prefer.
Here is the logging excerpt from the configuration:
logging {
channel default_file {
file "/var/log/named/single.log" versions 3 size 5m;
severity dynamic;
print-time local;
print-severity yes;
};
category default { default_file; };
};
With this single file logging configuration, all the other sections of
code produce what I expect to see from rndc trace 99.
When I use separate logs via:
logging {
channel default_file {
file "/var/log/named/default.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel general_file {
file "/var/log/named/general.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel database_file {
file "/var/log/named/database.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel security_file {
file "/var/log/named/security.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel config_file {
file "/var/log/named/config.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel resolver_file {
file "/var/log/named/resolver.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel xfer-in_file {
file "/var/log/named/xfer-in.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel xfer-out_file {
file "/var/log/named/xfer-out.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel notify_file {
file "/var/log/named/notify.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel client_file {
file "/var/log/named/client.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel unmatched_file {
file "/var/log/named/unmatched.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel queries_file {
file "/var/log/named/queries.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel network_file {
file "/var/log/named/network.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel update_file {
file "/var/log/named/update.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel dispatch_file {
file "/var/log/named/dispatch.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel dnssec_file {
file "/var/log/named/dnssec.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
channel lame-servers_file {
file "/var/log/named/lame-servers.log" versions 3 size 5m;
severity dynamic;
print-time yes;
};
category default { default_file; };
category general { general_file; };
category database { database_file; };
category security { security_file; };
category config { config_file; };
category resolver { resolver_file; };
category xfer-in { xfer-in_file; };
category xfer-out { xfer-out_file; };
category notify { notify_file; };
category client { client_file; };
category unmatched { unmatched_file; };
category queries { queries_file; };
category network { network_file; };
category update { update_file; };
category dispatch { dispatch_file; };
category dnssec { dnssec_file; };
category lame-servers { lame-servers_file; };
};
with 'rndc trace 99', all files except /var/log/named/update.log receive
copious amounts of information. The update log receives only the REFUSED
line like 'rndc trace 1' below.
With rndc trace 1 and single file logging I get:26-May-2024 23:23:59.522 info: client @0x7fb4df8ad968 <redacted> <redacted>: updating zone '<redacted>/IN': update failed: rejected by secure update (REFUSED)
at rndc trace 7:26-May-2024 23:26:21.611 debug 3: client @0x7fb4e4739568 <redacted>#42321: UDP request 26-May-2024 23:26:21.612 debug 5: client @0x7fb4e4739568 <redacted>#42321: using view '_default' 26-May-2024 23:26:21.612 debug 3: client @0x7fb4e4739568 <redacted>#42321: request has valid signature: <redacted> 26-May-2024 23:26:21.612 debug 3: client @0x7fb4e4739568 <redacted>#42321/key <redacted>: recursion available 26-May-2024 23:26:21.612 info: client @0x7fb4e4739568 <redacted>#42321/key <redacted>: updating zone '<redacted>/IN': update failed: rejected by secure update (REFUSED) 26-May-2024 23:26:21.612 debug 3: client @0x7fb4e4739568 <redacted>#42321/key <redacted>: reset client
at rndc trace 99: 26-May-2024 23:29:49.893 info: received control channel command 'trace 99' 26-May-2024 23:29:49.893 info: debug level is now 99 26-May-2024 23:29:49.893 debug 3: freeing control connection26-May-2024 23:29:50.323 debug 3: client @0x7fb4e0732b68 <redacted>#45079: UDP request 26-May-2024 23:29:50.323 debug 5: client @0x7fb4e0732b68 <redacted>#45079: using view '_default' 26-May-2024 23:29:50.323 debug 3: client @0x7fb4e0732b68 <redacted>#45079: request has valid signature: <redacted> 26-May-2024 23:29:50.323 debug 3: client @0x7fb4e0732b68 <redacted>#45079/key <redacted>: recursion available 26-May-2024 23:29:50.323 info: client @0x7fb4e0732b68 <redacted>#45079/key <redacted>: updating zone '<redacted>/IN': update failed: rejected by secure update (REFUSED) 26-May-2024 23:29:50.323 debug 3: client @0x7fb4e0732b68 <redacted>#45079/key <redacted>: reset client
26-May-2024 23:29:51.909 debug 3: allocate new control connection 26-May-2024 23:29:51.910 info: received control channel command 'trace 0' 26-May-2024 23:29:51.910 info: debug level is now 0 From nsupdate: nsupdate -L99 -dD -k TrueNAS.key nsupdate-cmds-py.txt setup_system() 27-May-2024 00:54:00.723 socket 0x556cc2a55250: created 27-May-2024 00:54:00.723 socket 0x556cc2a55250 <redacted>#58618: bound27-May-2024 00:54:00.723 dispatchmgr 0x556cc29b7830: dns_dispatch_createudp: Created UDP dispatch for <redacted>#0 with socket fd 20 27-May-2024 00:54:00.723 dispatchmgr 0x556cc29b7830: created UDP dispatcher 0x556cc2a54b30 27-May-2024 00:54:00.723 dispatch 0x556cc2a54b30: created task 0x556cc2a55510 27-May-2024 00:54:00.723 dispatch 0x556cc2a54b30: created socket 0x556cc2a55250
27-May-2024 00:54:00.723 socket 0x556cc2a55e50: created 27-May-2024 00:54:00.723 socket 0x556cc2a55e50 <redacted>#36512: bound27-May-2024 00:54:00.723 dispatchmgr 0x556cc29b7830: dns_dispatch_createudp: Created UDP dispatch for <redacted>#0 with socket fd 21 27-May-2024 00:54:00.723 dispatchmgr 0x556cc29b7830: created UDP dispatcher 0x556cc2a55730 27-May-2024 00:54:00.723 dispatch 0x556cc2a55730: created task 0x556cc2a55fd0 27-May-2024 00:54:00.723 dispatch 0x556cc2a55730: created socket 0x556cc2a55e50
27-May-2024 00:54:00.723 dns_requestmgr_create 27-May-2024 00:54:00.723 dns_requestmgr_create: 0x556cc2a56b20 Creating key... Creating key... namefromtext keycreate reset_system() user_interaction() do_next_command() do_next_command() do_next_command() evaluate_prereq() make_prereq() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() update_addordelete() do_next_command() start_update() send_update() Sending update to <redacted>#53 27-May-2024 00:54:00.723 dns_request_createvia27-May-2024 00:54:00.723 dispatch 0x556cc2a54b30 response 0x7fca10005d00 <redacted>#53: attached to task 0x556cc2a54840 27-May-2024 00:54:00.723 socket 0x556cc2a55250: socket_recv: event 0x7fca100031e0 -> task 0x556cc2a55510
27-May-2024 00:54:00.723 request_render27-May-2024 00:54:00.723 sockmgr 0x556cc2993a60 thread 0: watcher got message -3 for socket 20 27-May-2024 00:54:00.723 sockmgr 0x556cc2993a60 thread 0: watcher got message -2 for socket -1
27-May-2024 00:54:00.723 requestmgr_attach: 0x556cc2a56b20: eref 1 iref 1 27-May-2024 00:54:00.723 mgr_gethash 27-May-2024 00:54:00.723 req_send: request 0x7fca10005000 27-May-2024 00:54:00.723 dns_request_createvia: request 0x7fca10005000 show_message() Outgoing update query: ;; ->>HEADER<<- opcode: UPDATE, status: NOERROR, id: 13334 ;; flags:; ZONE: 1, PREREQ: 1, UPDATE: 9, ADDITIONAL: 1 ;; ZONE SECTION: ;<redacted>. IN SOA ;; PREREQUISITE SECTION: <redacted>. 0 ANY ANY ;; UPDATE SECTION: <redacted>. 0 ANY A <redacted>. 0 ANY AAAA <redacted>. 300 IN A <redacted> <redacted>. 300 IN AAAA <redacted> <redacted>. 300 IN A <redacted> <redacted>. 300 IN AAAA <redacted> <redacted>. 300 IN A <redacted> <redacted>. 300 IN A <redacted> <redacted>. 300 IN AAAA <redacted> ;; TSIG PSEUDOSECTION:<redacted>. 0 ANY TSIG <redacted>. 1716789240 300 32 <redacted> <redacted> NOERROR 0
27-May-2024 00:54:00.723 req_senddone: request 0x7fca1000500027-May-2024 00:54:00.779 socket 0x556cc2a55250: internal_recv: event 0x7fca100031e0 -> task 0x556cc2a55510 27-May-2024 00:54:00.779 socket 0x556cc2a55250 <redacted>#53: packet received correctly 27-May-2024 00:54:00.779 socket 0x556cc2a55250: processing cmsg 0x7fca16b8ea60 27-May-2024 00:54:00.779 socket 0x556cc2a55250: processing cmsg 0x7fca16b8ea80 27-May-2024 00:54:00.779 socket 0x556cc2a55250: interface received on ifindex 3 27-May-2024 00:54:00.779 socket 0x556cc2a55250: processing cmsg 0x7fca16b8eaa8 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: got packet: requests 1, buffers 1, recvs 1 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: got valid DNS message header, /QR 1, id 13334 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: search for response in bucket 0: found 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30 response 0x7fca10005d00 <redacted>#53: [a] Sent event 0x7fca100183a0 buffer 0x7fca10006130 len 65535 to task 0x556cc2a54840 27-May-2024 00:54:00.779 socket 0x556cc2a55250: socket_recv: event 0x7fca100181f0 -> task 0x556cc2a55510 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -3 for socket 20 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -2 for socket -1
27-May-2024 00:54:00.779 req_response: request 0x7fca10005000: success27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30 response 0x7fca10005d00 <redacted>#53: detaching from task 0x556cc2a54840
27-May-2024 00:54:00.779 req_cancel: request 0x7fca10005000 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: detach: refcount 2 27-May-2024 00:54:00.779 req_sendevent: request 0x7fca10005000 update_completed() 27-May-2024 00:54:00.779 dns_request_getresponse: request 0x7fca10005000 tsig verification successful show_message() Reply from update query: ;; ->>HEADER<<- opcode: UPDATE, status: REFUSED, id: 13334 ;; flags: qr; ZONE: 1, PREREQ: 0, UPDATE: 0, ADDITIONAL: 1 ;; ZONE SECTION: ;<redacted>. IN SOA ;; TSIG PSEUDOSECTION:<redacted>. 0 ANY TSIG <redacted>. 1716789236 300 32 <redacted> 13334 NOERROR 0
27-May-2024 00:54:00.779 dns_request_destroy: request 0x7fca10005000 27-May-2024 00:54:00.779 req_destroy: request 0x7fca10005000 27-May-2024 00:54:00.779 requestmgr_detach: 0x556cc2a56b20: eref 1 iref 0 done_update() reset_system() user_interaction() cleanup() detach tsigkey x0x556cc2997f30 Shutting down task manager shutdown_program() Shutting down request manager 27-May-2024 00:54:00.779 dns_requestmgr_shutdown: 0x556cc2a56b20 27-May-2024 00:54:00.779 send_shutdown_events: 0x556cc2a56b20 Destroy DST lib Destroying request manager27-May-2024 00:54:00.779 dns_requestmgr_detach: 0x556cc2a56b20: eref 0 iref 0
27-May-2024 00:54:00.779 mgr_destroy 27-May-2024 00:54:00.779 dispatch 0x556cc2a55730: detach: refcount 1 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: detach: refcount 1 Freeing the dispatchers 27-May-2024 00:54:00.779 dispatch 0x556cc2a55730: detach: refcount 0 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: detach: refcount 0 Shutting down dispatch manager27-May-2024 00:54:00.779 dispatchmgr 0x556cc29b7830: destroy_mgr_ok: shuttingdown=1, listnonempty=1,
27-May-2024 00:54:00.779 dispatchmgr 0x556cc29b7830: destroy: killit=027-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: got packet: requests 0, buffers 1, recvs 1 27-May-2024 00:54:00.779 dispatch 0x556cc2a54b30: shutting down; detaching from sock 0x556cc2a55250, task 0x556cc2a55510
27-May-2024 00:54:00.779 socket 0x556cc2a55250: destroying27-May-2024 00:54:00.779 dispatchmgr 0x556cc29b7830: destroy_mgr_ok: shuttingdown=1, listnonempty=1, 27-May-2024 00:54:00.779 dispatch 0x556cc2a55730: shutting down; detaching from sock 0x556cc2a55e50, task 0x556cc2a55fd0 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -5 for socket 20
27-May-2024 00:54:00.779 socket 0x556cc2a55e50: destroying27-May-2024 00:54:00.779 dispatchmgr 0x556cc29b7830: destroy_mgr_ok: shuttingdown=1, listnonempty=0, 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -2 for socket -1 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -5 for socket 21 27-May-2024 00:54:00.779 sockmgr 0x556cc2993a60 thread 0: watcher got message -2 for socket -1
Destroying event Shutting down socket manager27-May-2024 00:54:00.787 sockmgr 0x556cc2993a60 thread 0: watcher got message -1 for socket 0
27-May-2024 00:54:00.787 sockmgr 0x556cc2993a60 thread 0: watcher exiting Shutting down timer manager Removing log context Destroying memory context -Erik -------------------------------------------- Reference information -------------------------------------------- Compiled as: BIND 9.18.26 (Extended Support Version) <id:>running on Linux x86_64 6.8.10-300.fc40.x86_64 #1 SMP PREEMPT_DYNAMIC Fri May 17 21:20:54 UTC 2024 built by make with '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--runstatedir=/run' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--localstatedir=/var' '--with-pic' '--disable-static' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-libidn2' '--with-maxminddb' '--with-gssapi=yes' '--with-lmdb=yes' '--with-json-c' '--enable-dnstap' '--with-cmocka' '--enable-fixed-rrset' '--enable-full-report' 'CPPFLAGS= -DOPENSSL_API_COMPAT=10100' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CC=gcc' 'CFLAGS=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-U_FORTIFY_SOURCE,-D_FORTIFY_SOURCE=3 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -march=x86-64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Wno-complain-wrong-lang -Werror=format-security -Wp,-U_FORTIFY_SOURCE,-D_FORTIFY_SOURCE=3 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -march=x86-64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed -Wl,-z,pack-relative-relocs -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld-errors -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Wl,--build-id=sha1 -specs=/usr/lib/rpm/redhat/redhat-package-notes ' 'LT_SYS_LIBRARY_PATH=/usr/lib64:' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig'
compiled by GCC 14.0.1 20240411 (Red Hat 14.0.1-0) compiled with OpenSSL version: OpenSSL 3.2.1 30 Jan 2024 linked to OpenSSL version: OpenSSL 3.2.1 30 Jan 2024 compiled with libuv version: 1.48.0 linked to libuv version: 1.48.0 compiled with libnghttp2 version: 1.59.0 linked to libnghttp2 version: 1.59.0 compiled with libxml2 version: 2.12.6 linked to libxml2 version: 21207 compiled with json-c version: 0.17 linked to json-c version: 0.17 compiled with zlib version: 1.3.0.zlib-ng linked to zlib version: 1.3.0.zlib-ng linked to maxminddb version: 1.9.1 compiled with protobuf-c version: 1.5.0 linked to protobuf-c version: 1.5.0 threads support is enabledDNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
DS algorithms: SHA-1 SHA-256 SHA-384HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
TKEY mode 2 support (Diffie-Hellman): yes TKEY mode 3 support (GSS-API): yes default paths: named configuration: /etc/named.conf rndc configuration: /etc/rndc.conf DNSSEC root key: /etc/bind.keys nsupdate session key: /var/run/named/session.key named PID file: /var/run/named/named.pid named lock file: /var/run/named/named.lock geoip-directory: /usr/share/GeoIP On 5/26/24 11:11 PM, Mark Andrews wrote:
Start from the beginning. Show the actual configuration (named.conf, K* files, etc.). X out the secret keys. Show the actual commands you are running. Show the actual logs being produced. REFUSED can come from lots of things. Named emits log messages for almost all of them without needing to turn on debugging. Stop making us guess which version you BIND you upgraded from. This bind-users, not Fedora support. F36-F39 is meaningless here. If you are using nsupdate to send the UPDATE request turn on its debugging. At the moment all you have said is that you have a problem but have given NOTHING for people to work with to help you. Mark
OpenPGP_signature.asc
Description: OpenPGP digital signature
-- Visit https://lists.isc.org/mailman/listinfo/bind-users to unsubscribe from this list ISC funds the development of this software with paid support subscriptions. Contact us at https://www.isc.org/contact/ for more information. bind-users mailing list bind-users@lists.isc.org https://lists.isc.org/mailman/listinfo/bind-users
