Debugging TSIG signed nsupdate problems
Erik Edwards
erik at emedwards.info
Mon May 27 06:06:17 UTC 2024
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 connection
26-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: bound
27-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: bound
27-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_createvia
27-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_render
27-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 0x7fca10005000
27-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: success
27-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 manager
27-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 manager
27-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=0
27-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: destroying
27-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: destroying
27-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 manager
27-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 enabled
DNSSEC algorithms: RSASHA1 NSEC3RSASHA1 RSASHA256 RSASHA512
ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
DS algorithms: SHA-1 SHA-256 SHA-384
HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384
HMAC-SHA512
TKEY mode 2 support (Diffie-Hellman): yes
TKEY mode 3 support (GSS-API): yes
default paths:
named configuration: /etc/named.conf
rndc configuration: /etc/rndc.conf
DNSSEC root key: /etc/bind.keys
nsupdate session key: /var/run/named/session.key
named PID file: /var/run/named/named.pid
named lock file: /var/run/named/named.lock
geoip-directory: /usr/share/GeoIP
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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/bind-users/attachments/20240527/9efcbeea/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 236 bytes
Desc: OpenPGP digital signature
URL: <https://lists.isc.org/pipermail/bind-users/attachments/20240527/9efcbeea/attachment-0001.sig>
More information about the bind-users
mailing list