Answers for www.dnssec-failed.org with dnssec-validation auto;

John Thurston john.thurston at alaska.gov
Wed Apr 17 17:01:37 UTC 2024 

A fresh day, and a fresh idea - I just spun up a completely new instance 
of named, listening on its own port, with a stripped down config. Now 
the behavior is even stranger.

I can see the "no valid signature found" line in the server log, but my 
'dig' still gets an answer. What I can see in the logs tells me that 
named has determined the answer is invalid, but then it proceeds to 
deliver that answer to my client. I can't figure out why.

I feel like I am too far down into the weeds, and there is something 
basic I'm overlooking. Can anyone help re-orient me?


The .conf is pretty small, and looks like:

> controls {
>         inet 127.0.0.1 port 1953 allow {
>                 127.0.0.1/32;
>         } keys {
>                 "ns88-testPrimary-key";
>         };
> };
> options {
>         directory "/var/opt/testPrimary/named/data";
>         dump-file "cache_dump.db";
>         listen-on port 1053 {
>                 127.0.0.1/32;
>         };
>         querylog yes;
>         dnssec-validation auto;
>         empty-zones-enable no;
>         recursion yes;
> };
> key "ns88-testPrimary-key" {
>         algorithm "hmac-sha256";
>         secret "????????????????????????????????????????????";
> };

When I launch it in the foreground, the output looks like:

> 17-Apr-2024 08:17:46.934 starting BIND 9.18.24 (Extended Support 
> Version) <id:6d7674f>
> 17-Apr-2024 08:17:46.934 running on Linux x86_64 
> 5.14.0-362.18.1.el9_3.x86_64 #1 SMP PREEMPT_DYNAMIC Mon Jan 29 
> 07:05:48 EST 2024
> 17-Apr-2024 08:17:46.934 built with '--build=x86_64-redhat-linux-gnu' 
> '--host=x86_64-redhat-linux-gnu' '--program-prefix=' 
> '--disable-dependency-tracking' '--prefix=/opt/isc/isc-bind/root/usr' 
> '--exec-prefix=/opt/isc/isc-bind/root/usr' 
> '--bindir=/opt/isc/isc-bind/root/usr/bin' 
> '--sbindir=/opt/isc/isc-bind/root/usr/sbin' 
> '--sysconfdir=/etc/opt/isc/scls/isc-bind' 
> '--datadir=/opt/isc/isc-bind/root/usr/share' 
> '--includedir=/opt/isc/isc-bind/root/usr/include' 
> '--libdir=/opt/isc/isc-bind/root/usr/lib64' 
> '--libexecdir=/opt/isc/isc-bind/root/usr/libexec' 
> '--localstatedir=/var/opt/isc/scls/isc-bind' 
> '--sharedstatedir=/var/opt/isc/scls/isc-bind/lib' 
> '--mandir=/opt/isc/isc-bind/root/usr/share/man' 
> '--infodir=/opt/isc/isc-bind/root/usr/share/info' 
> '--enable-warn-error' '--disable-static' '--enable-dnstap' 
> '--with-pic' '--with-gssapi' '--with-json-c' '--with-libxml2' 
> '--without-lmdb' '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,-D_FORTIFY_SOURCE=2 
> -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-v2 
> -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection 
> -fcf-protection -fno-omit-frame-pointer' 'LDFLAGS=-Wl,-z,relro 
> -Wl,--as-needed -Wl,-z,now 
> -specs=/usr/lib/rpm/redhat/redhat-hardened-ld 
> -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 
> -L/opt/isc/isc-bind/root/usr/lib64' 'CPPFLAGS= 
> -I/opt/isc/isc-bind/root/usr/include' 'LT_SYS_LIBRARY_PATH=/usr/lib64' 
> 'PKG_CONFIG_PATH=:/opt/isc/isc-bind/root/usr/lib64/pkgconfig:/opt/isc/isc-bind/root/usr/share/pkgconfig' 
> 'SPHINX_BUILD=/builddir/build/BUILD/bind-9.18.24/sphinx/bin/sphinx-build'
> 17-Apr-2024 08:17:46.934 running as: named -g -4 -D testPrimary -n 1 
> -u named -c /etc/opt/testPrimary/named.conf
> 17-Apr-2024 08:17:46.934 compiled by GCC 11.4.1 20230605 (Red Hat 
> 11.4.1-2)
> 17-Apr-2024 08:17:46.934 compiled with OpenSSL version: OpenSSL 3.0.7 
> 1 Nov 2022
> 17-Apr-2024 08:17:46.934 linked to OpenSSL version: OpenSSL 3.0.7 1 
> Nov 2022
> 17-Apr-2024 08:17:46.934 compiled with libuv version: 1.44.2
> 17-Apr-2024 08:17:46.934 linked to libuv version: 1.44.2
> 17-Apr-2024 08:17:46.934 compiled with libxml2 version: 2.9.13
> 17-Apr-2024 08:17:46.934 linked to libxml2 version: 20913
> 17-Apr-2024 08:17:46.934 compiled with json-c version: 0.14
> 17-Apr-2024 08:17:46.934 linked to json-c version: 0.14
> 17-Apr-2024 08:17:46.934 compiled with zlib version: 1.2.11
> 17-Apr-2024 08:17:46.935 linked to zlib version: 1.2.11
> 17-Apr-2024 08:17:46.935 
> ----------------------------------------------------
> 17-Apr-2024 08:17:46.935 BIND 9 is maintained by Internet Systems 
> Consortium,
> 17-Apr-2024 08:17:46.935 Inc. (ISC), a non-profit 501(c)(3) public-benefit
> 17-Apr-2024 08:17:46.935 corporation.  Support and training for BIND 9 are
> 17-Apr-2024 08:17:46.935 available at https://www.isc.org/support
> 17-Apr-2024 08:17:46.935 
> ----------------------------------------------------
> 17-Apr-2024 08:17:46.935 adjusted limit on open files from 524288 to 
> 1048576
> 17-Apr-2024 08:17:46.935 found 1 CPU, using 1 worker thread
> 17-Apr-2024 08:17:46.935 using 1 UDP listener per interface
> 17-Apr-2024 08:17:46.936 DNSSEC algorithms: RSASHA256 RSASHA512 
> ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
> 17-Apr-2024 08:17:46.936 DS algorithms: SHA-1 SHA-256 SHA-384
> 17-Apr-2024 08:17:46.936 HMAC algorithms: HMAC-MD5 HMAC-SHA1 
> HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
> 17-Apr-2024 08:17:46.936 TKEY mode 2 support (Diffie-Hellman): yes
> 17-Apr-2024 08:17:46.936 TKEY mode 3 support (GSS-API): yes
> 17-Apr-2024 08:17:46.938 loading configuration from 
> '/etc/opt/testPrimary/named.conf'
> 17-Apr-2024 08:17:46.938 unable to open 
> '/etc/opt/isc/scls/isc-bind/bind.keys'; using built-in keys instead
> 17-Apr-2024 08:17:46.940 using default UDP/IPv4 port range: [32768, 60999]
> 17-Apr-2024 08:17:46.941 listening on IPv4 interface lo, 127.0.0.1#1053
> 17-Apr-2024 08:17:46.941 generating session key for dynamic DNS
> 17-Apr-2024 08:17:46.941 sizing zone task pool based on 0 zones
> 17-Apr-2024 08:17:46.941 none:98: 'max-cache-size 90%' - setting to 
> 1558MB (out of 1732MB)
> 17-Apr-2024 08:17:46.942 using built-in root key for view _default
> 17-Apr-2024 08:17:46.942 set up managed keys zone for view _default, 
> file 'managed-keys.bind'
> 17-Apr-2024 08:17:46.943 command channel listening on 127.0.0.1#1953
> 17-Apr-2024 08:17:46.943 not using config file logging statement for 
> logging due to -g option
> 17-Apr-2024 08:17:46.945 managed-keys-zone: loaded serial 2
> 17-Apr-2024 08:17:46.945 all zones loaded
> 17-Apr-2024 08:17:46.945 running
> 17-Apr-2024 08:17:46.979 managed-keys-zone: Key 20326 for zone . is 
> now trusted (acceptance timer complete)
> 17-Apr-2024 08:17:46.981 resolver priming query complete: success

And when I query it (gratuitous flush) with

> rndc -k rndc.key -s localhost -p 1953 flush && dig -4 -p 1053 
> @localhost www.dnssec-failed.org.

This is what is logged

> 17-Apr-2024 08:20:13.008 received control channel command 'flush'
> 17-Apr-2024 08:20:13.010 flushing caches in all views succeeded
> 17-Apr-2024 08:20:13.030 client @0x7feda09ce768 127.0.0.1#36320 
> (www.dnssec-failed.org): query: www.dnssec-failed.org IN A +E(0)K 
> (127.0.0.1)
> 17-Apr-2024 08:20:13.132 resolver priming query complete: success
> 17-Apr-2024 08:20:13.485 validating www.dnssec-failed.org/A: no valid 
> signature found

And this is the output of dig

> ; <<>> DiG 9.18.24 <<>> -4 -p 1053 @localhost www.dnssec-failed.org.
> ; (2 servers found)
> ;; global options: +cmd
> ;; Got answer:
> ;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 9625
> ;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1
>
> ;; OPT PSEUDOSECTION:
> ; EDNS: version: 0, flags:; udp: 1232
> ; COOKIE: 9e74c986c617414a01000000661ff6bd07eca9a95d995f7f (good)
> ;; QUESTION SECTION:
> ;www.dnssec-failed.org.         IN      A
>
> ;; ANSWER SECTION:
> www.dnssec-failed.org. 7200    IN      A       68.87.109.242
> www.dnssec-failed.org. 7200    IN      A       69.252.193.191
>
> ;; Query time: 515 msec
> ;; SERVER: 127.0.0.1#1053(localhost) (UDP)
> ;; WHEN: Wed Apr 17 08:20:13 AKDT 2024
> ;; MSG SIZE  rcvd: 110

When I crank the dnssec logging severity to debug-7, I see the following:

> 17-Apr-2024 08:39:25.601 managed-keys-zone: Creating key fetch in 
> zone_refreshkeys() for '.'
> 17-Apr-2024 08:39:25.696 managed-keys-zone: Returned from key fetch in 
> keyfetch_done() for '.': success
> 17-Apr-2024 08:39:25.696 managed-keys-zone: Verifying DNSKEY set for 
> zone '.' using DS 20326/8: success
> 17-Apr-2024 08:39:25.696 managed-keys-zone: Key 20326 for zone . is 
> now trusted (acceptance timer complete)
> 17-Apr-2024 08:39:25.697 validating ./NS: starting
> 17-Apr-2024 08:39:25.698 validating ./NS: attempting positive response 
> validation
> 17-Apr-2024 08:39:25.698   validating ./DNSKEY: starting
> 17-Apr-2024 08:39:25.698   validating ./DNSKEY: attempting positive 
> response validation
> 17-Apr-2024 08:39:25.698   validating ./DNSKEY: verify rdataset 
> (keyid=20326): success
> 17-Apr-2024 08:39:25.698   validating ./DNSKEY: marking as secure (DS)
> 17-Apr-2024 08:39:25.698   validator @0x7fb8722b7000: 
> dns_validator_destroy
> 17-Apr-2024 08:39:25.698 validating ./NS: in validator_callback_dnskey
> 17-Apr-2024 08:39:25.698 validating ./NS: keyset with trust secure
> 17-Apr-2024 08:39:25.698 validating ./NS: resuming validate
> 17-Apr-2024 08:39:25.698 validating ./NS: verify rdataset 
> (keyid=5613): success
> 17-Apr-2024 08:39:25.698 validating ./NS: marking as secure, noqname 
> proof not needed
> 17-Apr-2024 08:39:25.698 validator @0x7fb872276c00: dns_validator_destroy
> 17-Apr-2024 08:40:39.814 validating ./NS: starting
> 17-Apr-2024 08:40:39.815 validating ./NS: attempting positive response 
> validation
> 17-Apr-2024 08:40:39.882 validating ./DNSKEY: starting
> 17-Apr-2024 08:40:39.882 validating ./DNSKEY: attempting positive 
> response validation
> 17-Apr-2024 08:40:39.883 validating ./DNSKEY: verify rdataset 
> (keyid=20326): success
> 17-Apr-2024 08:40:39.883 validating ./DNSKEY: marking as secure (DS)
> 17-Apr-2024 08:40:39.883 validator @0x7fb8722ba200: dns_validator_destroy
> 17-Apr-2024 08:40:39.883 validating ./NS: in fetch_callback_dnskey
> 17-Apr-2024 08:40:39.883 validating ./NS: keyset with trust secure
> 17-Apr-2024 08:40:39.883 validating ./NS: resuming validate
> 17-Apr-2024 08:40:39.883 validating ./NS: verify rdataset 
> (keyid=5613): success
> 17-Apr-2024 08:40:39.883 validating ./NS: marking as secure, noqname 
> proof not needed
> 17-Apr-2024 08:40:39.883 validator @0x7fb8722b7000: dns_validator_destroy
> 17-Apr-2024 08:40:40.288 validating www.dnssec-failed.org/A: starting
> 17-Apr-2024 08:40:40.288 validating www.dnssec-failed.org/A: 
> attempting positive response validation
> 17-Apr-2024 08:40:40.288 validating www.dnssec-failed.org/A: no valid 
> signature found
> 17-Apr-2024 08:40:40.288 validating www.dnssec-failed.org/A: falling 
> back to insecurity proof
> 17-Apr-2024 08:40:40.288 validating www.dnssec-failed.org/A: checking 
> existence of DS at 'org'
> 17-Apr-2024 08:40:40.288   validating org/DS: starting
> 17-Apr-2024 08:40:40.288   validating org/DS: attempting positive 
> response validation
> 17-Apr-2024 08:40:40.288   validating org/DS: keyset with trust secure
> 17-Apr-2024 08:40:40.288   validating org/DS: verify rdataset 
> (keyid=5613): success
> 17-Apr-2024 08:40:40.289   validating org/DS: marking as secure, 
> noqname proof not needed
> 17-Apr-2024 08:40:40.289   validator @0x7fb8722b7a00: 
> dns_validator_destroy
> 17-Apr-2024 08:40:40.289 validating www.dnssec-failed.org/A: in 
> validator_callback_ds
> 17-Apr-2024 08:40:40.289 validating www.dnssec-failed.org/A: dsset 
> with trust secure
> 17-Apr-2024 08:40:40.289 validating www.dnssec-failed.org/A: resuming 
> proveunsecure
> 17-Apr-2024 08:40:40.289 validating www.dnssec-failed.org/A: checking 
> existence of DS at 'dnssec-failed.org'
> 17-Apr-2024 08:40:40.289   validating dnssec-failed.org/DS: starting
> 17-Apr-2024 08:40:40.289   validating dnssec-failed.org/DS: attempting 
> positive response validation
> 17-Apr-2024 08:40:40.322 validating org/DNSKEY: starting
> 17-Apr-2024 08:40:40.322 validating org/DNSKEY: attempting positive 
> response validation
> 17-Apr-2024 08:40:40.322 validating org/DNSKEY: verify rdataset 
> (keyid=26974): success
> 17-Apr-2024 08:40:40.322 validating org/DNSKEY: marking as secure (DS)
> 17-Apr-2024 08:40:40.322 validator @0x7fb8722b7000: dns_validator_destroy
> 17-Apr-2024 08:40:40.323   validating dnssec-failed.org/DS: in 
> fetch_callback_dnskey
> 17-Apr-2024 08:40:40.323   validating dnssec-failed.org/DS: keyset 
> with trust secure
> 17-Apr-2024 08:40:40.323   validating dnssec-failed.org/DS: resuming 
> validate
> 17-Apr-2024 08:40:40.323   validating dnssec-failed.org/DS: verify 
> rdataset (keyid=3093): success
> 17-Apr-2024 08:40:40.323   validating dnssec-failed.org/DS: marking as 
> secure, noqname proof not needed
> 17-Apr-2024 08:40:40.323   validator @0x7fb8722b7a00: 
> dns_validator_destroy
> 17-Apr-2024 08:40:40.323 validating www.dnssec-failed.org/A: in 
> validator_callback_ds
> 17-Apr-2024 08:40:40.323 validating www.dnssec-failed.org/A: dsset 
> with trust secure
> 17-Apr-2024 08:40:40.323 validating www.dnssec-failed.org/A: resuming 
> proveunsecure
> 17-Apr-2024 08:40:40.323 validating www.dnssec-failed.org/A: no 
> supported algorithm/digest (dnssec-failed.org/DS)
> 17-Apr-2024 08:40:40.323 validating www.dnssec-failed.org/A: marking 
> as answer (proveunsecure (2))
> 17-Apr-2024 08:40:40.323 validator @0x7fb8722b8e00: dns_validator_destroy



--
Do things because you should, not just because you can.

John Thurston    907-465-8591
John.Thurston at alaska.gov
Department of Administration
State of Alaska

On 4/17/2024 12:26 AM, Nick Tait via bind-users wrote:
> If you have just a single process listening on port 53, then I'd 
> suggest using "tail -f" to watch your BIND logs
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.isc.org/pipermail/bind-users/attachments/20240417/af33b6ef/attachment-0001.htm>

More information about the bind-users mailing list