Pi-hole + unbound default setup not working on validation

Help
1

Please follow the below template, it will help us to help you!

Expected Behaviour:

Test validation

You can test DNSSEC validation using

dig fail01.dnssec.works @127.0.0.1 -p 5335
dig dnssec.works @127.0.0.1 -p 5335

The first command should give a status report of SERVFAIL and no IP address. The second should give NOERROR plus an IP address.

Actual Behaviour:

$ dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 5332
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 11 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sat Dec 03 09:43:31 CST 2022
;; MSG SIZE  rcvd: 41

Debug Token:

https://tricorder.pi-hole.net/7Vk3ac2d/

Hello internet.

I've been struggling for the last couple of days on setting up a pi-hole with unbound for personal usage. I noticed on my configuration that I get up to the point where I can safely assume that unbound is resolving, however all the requests get the status of SERVFAIL.

After research, trial and error and reflashing the pi (more times than I can count at this point), I still haven't figured out what the issue might be.

I'm using the "default" settings on the unbound setup in the pi-hole documentation, along with added debugging logs with level 3 verbosity.

sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*
/etc/unbound/unbound.conf:include-toplevel: "/etc/unbound/unbound.conf.d/*.conf"
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:server:
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:    auto-trust-anchor-file: "/var/lib/unbound/root.key"
/etc/unbound/unbound.conf.d/pi-hole.conf:server:
/etc/unbound/unbound.conf.d/pi-hole.conf:    logfile: "/var/log/unbound/unbound.log"
/etc/unbound/unbound.conf.d/pi-hole.conf:    verbosity: 3
/etc/unbound/unbound.conf.d/pi-hole.conf:    interface: 127.0.0.1
/etc/unbound/unbound.conf.d/pi-hole.conf:    port: 5335
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-ip4: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-udp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-tcp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    do-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    prefer-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    harden-glue: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    harden-dnssec-stripped: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    use-caps-for-id: no
/etc/unbound/unbound.conf.d/pi-hole.conf:    edns-buffer-size: 1232
/etc/unbound/unbound.conf.d/pi-hole.conf:    prefetch: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:    num-threads: 1
/etc/unbound/unbound.conf.d/pi-hole.conf:    so-rcvbuf: 1m
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 192.168.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 169.254.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 172.16.0.0/12
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: 10.0.0.0/8
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: fd00::/8
/etc/unbound/unbound.conf.d/pi-hole.conf:    private-address: fe80::/10

Any guidance or debug steps I'll follow as closely as possible.

Thanks in advance.

2

When this crops up it's commonly that the system clock or timezone is wrong. This causes the DNSSEC signatures to fail on everything.

On the Pi run the command below to check the local time, universal time, time zone, sync of system clock and if NTP is enabled.

datetimectl

See this page for commands needed to enable NTP, set correct timezone, etc if needed.

If it was time related, does that fix the SERVFAIL problem when you re-run those tests?

3

Hi chrislph, thanks for the response.

I flashed and tried again earlier today while posting this and I did verify that the system clock synch was marking yes. I thought maybe letting it sit for a couple of hours might help, but I'm still having the issue:

aamm19@pihole:~ $ timedatectl
               Local time: Sat 2022-12-03 14:21:36 CST
           Universal time: Sat 2022-12-03 20:21:36 UTC
                 RTC time: n/a
                Time zone: America/Monterrey (CST, -0600)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
aamm19@pihole:~ $ dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 60058
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 1395 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sat Dec 03 14:24:20 CST 2022
;; MSG SIZE  rcvd: 41
4

Did you install Unbound using apt install or a different way? If using a different way, have you added the root hints file mentioned in the guide (if using apt install then they're added and updated automatically)?

I'm not sure what else it is, others will have seen Unbound for longer and have more ideas.

You could try upping the logging level to get more info. First of all follow the log instructions at near the end of the guide to create a dedicated log file in /var/log/unbound/unbound.log. Then increase the verbosity level to 4, and it's also useful to enable human readable timestamps in `pi-hole.conf and restart the Unbound service.

# If no logfile is specified, syslog is used
logfile: "/var/log/unbound/unbound.log"
log-time-ascii: yes
verbosity: 4

Now do some domain tests and the log will contain lots of extra info about what's going on, what's failing and so on.

Once the problem is eventually fixed, you can put the verbosity back to 0, restart the Unbound service, and use the command below to empty the log file.

sudo truncate -s 0 /var/log/unbound/unbound.log
5

Did you install Unbound using apt install or a different way? If using a different way, have you added the root hints file mentioned in the guide (if using apt install then they're added and updated automatically)?

Yeah, I installed it through apt install. There is a note about downloading the current root.hints, so I did that just now as well.

wget https://www.internic.net/domain/named.root -qO- | sudo tee /var/lib/unbound/root.hints

This is the corresponding test I did along with the log

aamm19@pihole:~ $ date
Sun Dec  4 03:01:24 CST 2022
aamm19@pihole:~ $ dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 20064
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 31 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sun Dec 04 03:01:26 CST 2022
;; MSG SIZE  rcvd: 41

/var/log/unbound/unbound.log

Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: start
Dec 04 03:01:26 unbound[27080:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Dec 04 03:01:26 unbound[27080:0] info: subnet operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: subnet: not found in cache. pass to next module
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: subnet module exit state is module_wait_module
Dec 04 03:01:26 unbound[27080:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Dec 04 03:01:26 unbound[27080:0] info: validator operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: validator: pass to next module
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: validator module exit state is module_wait_module
Dec 04 03:01:26 unbound[27080:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Dec 04 03:01:26 unbound[27080:0] debug: process_request: new external request event
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state INIT REQUEST STATE
Dec 04 03:01:26 unbound[27080:0] info: resolving dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: request has dependency depth of 0
Dec 04 03:01:26 unbound[27080:0] debug: cache delegation returns delegpt
Dec 04 03:01:26 unbound[27080:0] info: DelegationPoint<.>: 13 names (7 missing), 19 addrs (0 result, 19 avail) cacheNS
Dec 04 03:01:26 unbound[27080:0] info:   b.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   a.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   m.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   l.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   k.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   j.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   i.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   h.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   g.root-servers.net.  A
Dec 04 03:01:26 unbound[27080:0] info:   f.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   e.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   d.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   c.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Dec 04 03:01:26 unbound[27080:0] info: resolving (init part 2):  dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Dec 04 03:01:26 unbound[27080:0] info: resolving (init part 3):  dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Dec 04 03:01:26 unbound[27080:0] info: processQueryTargets: dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Dec 04 03:01:26 unbound[27080:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (0 result, 19 avail) cacheNS
Dec 04 03:01:26 unbound[27080:0] info:   b.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   a.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   m.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   l.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   k.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   j.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   i.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   h.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   g.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   f.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   e.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   d.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   c.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug: removing 1 labels
Dec 04 03:01:26 unbound[27080:0] debug: attempt to get extra 3 targets
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=133 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=247 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=251 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=199 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=162 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=288 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=252 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=161 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=288 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=306 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=293 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=106 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=233 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: selrtt 360106
Dec 04 03:01:26 unbound[27080:0] debug: chase to recursion lame server
Dec 04 03:01:26 unbound[27080:0] debug: chase to dnssec lame server
Dec 04 03:01:26 unbound[27080:0] info: sending query: works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: sending to target: <.> 199.9.14.201#53
Dec 04 03:01:26 unbound[27080:0] debug: dnssec status: expected but lame_query anyway
Dec 04 03:01:26 unbound[27080:0] debug: EDNS lookup known=1 vs=0
Dec 04 03:01:26 unbound[27080:0] debug: serviced query UDP timeout=133 msec
Dec 04 03:01:26 unbound[27080:0] debug: inserted new pending reply id=f21e
Dec 04 03:01:26 unbound[27080:0] debug: opened UDP if=0 port=35744
Dec 04 03:01:26 unbound[27080:0] debug: comm point start listening 18 (-1 msec)
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: iterator module exit state is module_wait_reply
Dec 04 03:01:26 unbound[27080:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 03:01:26 unbound[27080:0] info: 0RDd mod2 rep dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: cache memory msg=69665 rrset=73368 infra=11669 val=66537 subnet=74504
Dec 04 03:01:26 unbound[27080:0] debug: answer cb
Dec 04 03:01:26 unbound[27080:0] debug: Incoming reply id = f21e
Dec 04 03:01:26 unbound[27080:0] debug: Incoming reply addr = ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug: lookup size is 1 entries
Dec 04 03:01:26 unbound[27080:0] debug: received udp reply.
Dec 04 03:01:26 unbound[27080:0] debug: udp message[91:0] F21E8180000100000001000005776F726B730000010001C00C0006000100000C7600380476306E30036E6963C00C0A686F73746D617374657206646F6E75747305656D61696C00638C5D5D00001C20000003840012750000000E10
Dec 04 03:01:26 unbound[27080:0] debug: outnet handle udp reply
Dec 04 03:01:26 unbound[27080:0] debug: measured roundtrip at 13 msec
Dec 04 03:01:26 unbound[27080:0] debug: svcd callbacks start
Dec 04 03:01:26 unbound[27080:0] debug: worker svcd callback for qstate 0x55bf345700
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: start
Dec 04 03:01:26 unbound[27080:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 04 03:01:26 unbound[27080:0] info: iterator operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: process_response: new external response event
Dec 04 03:01:26 unbound[27080:0] info: scrub for . NS IN
Dec 04 03:01:26 unbound[27080:0] info: response for dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] info: reply from <.> 199.9.14.201#53
Dec 04 03:01:26 unbound[27080:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 
;; QUESTION SECTION:
works.  IN      A

;; ANSWER SECTION:

;; AUTHORITY SECTION:
works.  3190    IN      SOA     v0n0.nic.works. hostmaster.donuts.email. 1670143325 7200 900 1209600 3600

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 91

Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 04 03:01:26 unbound[27080:0] info: query response was nodata ANSWER
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Dec 04 03:01:26 unbound[27080:0] info: processQueryTargets: dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 1
Dec 04 03:01:26 unbound[27080:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (19 result, 0 avail) cacheNS
Dec 04 03:01:26 unbound[27080:0] info:   b.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   a.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   m.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   l.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   k.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   j.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   i.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   h.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   g.root-servers.net. * A
Dec 04 03:01:26 unbound[27080:0] info:   f.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   e.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   d.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] info:   c.root-servers.net. * A AAAA
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 03:01:26 unbound[27080:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug: attempt to get extra 3 targets
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=233 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=106 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=293 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=306 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=288 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=161 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=252 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=288 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=162 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=199 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=251 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=247 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug:    rtt=110 REC_LAME
Dec 04 03:01:26 unbound[27080:0] debug: selrtt 360106
Dec 04 03:01:26 unbound[27080:0] debug: chase to recursion lame server
Dec 04 03:01:26 unbound[27080:0] debug: chase to dnssec lame server
Dec 04 03:01:26 unbound[27080:0] info: sending query: dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: sending to target: <.> 198.97.190.53#53
Dec 04 03:01:26 unbound[27080:0] debug: dnssec status: expected but lame_query anyway
Dec 04 03:01:26 unbound[27080:0] debug: EDNS lookup known=1 vs=0
Dec 04 03:01:26 unbound[27080:0] debug: serviced query UDP timeout=161 msec
Dec 04 03:01:26 unbound[27080:0] debug: inserted new pending reply id=784e
Dec 04 03:01:26 unbound[27080:0] debug: opened UDP if=0 port=7713
Dec 04 03:01:26 unbound[27080:0] debug: comm point start listening 19 (-1 msec)
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: iterator module exit state is module_wait_reply
Dec 04 03:01:26 unbound[27080:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 03:01:26 unbound[27080:0] info: 0RDd mod2 rep dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: cache memory msg=69912 rrset=73662 infra=11669 val=66537 subnet=74504
Dec 04 03:01:26 unbound[27080:0] debug: svcd callbacks end
Dec 04 03:01:26 unbound[27080:0] debug: close of port 35744
Dec 04 03:01:26 unbound[27080:0] debug: close fd 18
Dec 04 03:01:26 unbound[27080:0] debug: answer cb
Dec 04 03:01:26 unbound[27080:0] debug: Incoming reply id = 784e
Dec 04 03:01:26 unbound[27080:0] debug: Incoming reply addr = ip4 198.97.190.53 port 53 (len 16)
Dec 04 03:01:26 unbound[27080:0] debug: lookup size is 1 entries
Dec 04 03:01:26 unbound[27080:0] debug: received udp reply.
Dec 04 03:01:26 unbound[27080:0] debug: udp message[46:0] 784E8180000100010000000006646E7373656305776F726B730000010001C00C0001000100000C760004052D6B58
Dec 04 03:01:26 unbound[27080:0] debug: outnet handle udp reply
Dec 04 03:01:26 unbound[27080:0] debug: measured roundtrip at 16 msec
Dec 04 03:01:26 unbound[27080:0] debug: svcd callbacks start
Dec 04 03:01:26 unbound[27080:0] debug: worker svcd callback for qstate 0x55bf345700
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: start
Dec 04 03:01:26 unbound[27080:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 04 03:01:26 unbound[27080:0] info: iterator operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: process_response: new external response event
Dec 04 03:01:26 unbound[27080:0] info: scrub for . NS IN
Dec 04 03:01:26 unbound[27080:0] info: response for dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] info: reply from <.> 198.97.190.53#53
Dec 04 03:01:26 unbound[27080:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
dnssec.works.   IN      A

;; ANSWER SECTION:
dnssec.works.   3190    IN      A       5.45.107.88

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 46

Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 04 03:01:26 unbound[27080:0] info: query response was ANSWER
Dec 04 03:01:26 unbound[27080:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 04 03:01:26 unbound[27080:0] info: finishing processing for dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: iterator module exit state is module_finished
Dec 04 03:01:26 unbound[27080:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 04 03:01:26 unbound[27080:0] info: validator operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: validator: nextmodule returned
Dec 04 03:01:26 unbound[27080:0] debug: val handle processing q with state VAL_INIT_STATE
Dec 04 03:01:26 unbound[27080:0] debug: validator classification positive
Dec 04 03:01:26 unbound[27080:0] info: no signer, using dnssec.works. TYPE0 CLASS0
Dec 04 03:01:26 unbound[27080:0] debug: val handle processing q with state VAL_FINISHED_STATE
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: validator module exit state is module_finished
Dec 04 03:01:26 unbound[27080:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 04 03:01:26 unbound[27080:0] info: subnet operate: query dnssec.works. A IN
Dec 04 03:01:26 unbound[27080:0] debug: mesh_run: subnet module exit state is module_finished
Dec 04 03:01:26 unbound[27080:0] debug: query took 0.029852 sec
Dec 04 03:01:26 unbound[27080:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 03:01:26 unbound[27080:0] info: average recursion processing time 0.029852 sec
Dec 04 03:01:26 unbound[27080:0] info: histogram of recursion processing times
Dec 04 03:01:26 unbound[27080:0] info: [25%]=0 median[50%]=0 [75%]=0
Dec 04 03:01:26 unbound[27080:0] info: lower(secs) upper(secs) recursions
Dec 04 03:01:26 unbound[27080:0] info:    0.016384    0.032768 1
Dec 04 03:01:26 unbound[27080:0] debug: cache memory msg=70166 rrset=73906 infra=11669 val=66537 subnet=74504
Dec 04 03:01:26 unbound[27080:0] debug: svcd callbacks end
Dec 04 03:01:26 unbound[27080:0] debug: close of port 7713
Dec 04 03:01:26 unbound[27080:0] debug: close fd 19
6

My interpretation of that log portion is that the result is being returned sucessfully but it's failing validation at some point in the entire process. And your dig flags seem to support that; they're missing ad for Authenticated Data.

;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 5332
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

When I run the exact same command for that domain for Unbound I get

;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 23848
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

A couple of other things you can try. First, in the pi-hole.conf file add in the line below to enable validation logging. The restart the Unbound service as before so it picks up the change.

val-log-level: 2

This causes Unbound to report in the log file what it thinks is going wrong with DNSSEC validations. You might want to do that earlier truncate command to clear the log out if it's getting a bit unweildly. Now you can do more dig commands and see what extra info is being reported. Is the validation reporting what's going wrong?

Secondly, bit of a hack but is your Pi-hole set up to use Unbound, ie you're using localhost#5335 as the single upstream server? If so, try the dig command again but this time leave the port parameter off.

dig dnssec.works @127.0.0.1

This will send it through Pi-hole which in turn will send it through Unbound anyway, and it will still fail. But now you can look at the Query Log and see how Pi-hole is interpreting the result. Maybe BOGUS or something else.

The devs are DNS gurus who can likely home in on what's wrong from the extra logging.

EDIT: I added the extra logging to my Unbound to compare my log with yours. I'm not seeing the "lame" references and my UDP replies are way longer. I'm wondering if your ISP router is doing something funny with outbound requests, like capturing and redirecting them or something like that.

7

I assume every DIG to Unbound is returning SERVFAIL. If so the trust anchor probably isn't getting primed properly.

You can test it with: ('-v' flag is just verbose)
sudo -u unbound unbound-anchor -v

If it's good you'll see the following otherwise you'll get an error.
sudo -u unbound unbound-anchor -v
/var/lib/unbound/root.key has content
success: the anchor is ok

8

I added the val-log-level:2 line and I did see some interesting stuff. Specifically:
validation failure <dnssec.works. A IN>: key for validation . is marked as invalid because of a previous validation failure <. DNSKEY IN>: no signatures from 192.5.5.241 for trust anchor . while building chain of trust

But I can't say for sure what to make of that.

aamm19@pihole:~ $ dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 33930
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 27 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sun Dec 04 12:10:44 CST 2022
;; MSG SIZE  rcvd: 41


aamm19@pihole:~ $ tail -f /var/log/unbound/unbound.log 
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: start
Dec 04 12:10:44 unbound[31914:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Dec 04 12:10:44 unbound[31914:0] info: subnet operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: subnet: not found in cache. pass to next module
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: subnet module exit state is module_wait_module
Dec 04 12:10:44 unbound[31914:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Dec 04 12:10:44 unbound[31914:0] info: validator operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: validator: pass to next module
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: validator module exit state is module_wait_module
Dec 04 12:10:44 unbound[31914:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Dec 04 12:10:44 unbound[31914:0] debug: process_request: new external request event
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state INIT REQUEST STATE
Dec 04 12:10:44 unbound[31914:0] info: resolving dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: request has dependency depth of 0
Dec 04 12:10:44 unbound[31914:0] debug: cache delegation returns delegpt
Dec 04 12:10:44 unbound[31914:0] info: DelegationPoint<.>: 13 names (7 missing), 19 addrs (0 result, 19 avail) cacheNS
Dec 04 12:10:44 unbound[31914:0] info:   a.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   m.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   l.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   k.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   j.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   i.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   h.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   g.root-servers.net.  A
Dec 04 12:10:44 unbound[31914:0] info:   f.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   e.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   d.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   c.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   b.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Dec 04 12:10:44 unbound[31914:0] info: resolving (init part 2):  dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Dec 04 12:10:44 unbound[31914:0] info: resolving (init part 3):  dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Dec 04 12:10:44 unbound[31914:0] info: processQueryTargets: dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Dec 04 12:10:44 unbound[31914:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (0 result, 19 avail) cacheNS
Dec 04 12:10:44 unbound[31914:0] info:   a.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   m.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   l.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   k.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   j.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   i.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   h.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   g.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   f.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   e.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   d.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   c.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   b.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug: removing 1 labels
Dec 04 12:10:44 unbound[31914:0] debug: attempt to get extra 3 targets
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=159 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=187 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=200 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=230 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=187 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=234 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=302 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=242 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=110 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=196 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=233 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=297 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=239 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: selrtt 360110
Dec 04 12:10:44 unbound[31914:0] debug: chase to recursion lame server
Dec 04 12:10:44 unbound[31914:0] debug: chase to dnssec lame server
Dec 04 12:10:44 unbound[31914:0] info: sending query: works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: sending to target: <.> 192.33.4.12#53
Dec 04 12:10:44 unbound[31914:0] debug: dnssec status: expected but lame_query anyway
Dec 04 12:10:44 unbound[31914:0] debug: EDNS lookup known=1 vs=0
Dec 04 12:10:44 unbound[31914:0] debug: serviced query UDP timeout=297 msec
Dec 04 12:10:44 unbound[31914:0] debug: inserted new pending reply id=c888
Dec 04 12:10:44 unbound[31914:0] debug: opened UDP if=0 port=46742
Dec 04 12:10:44 unbound[31914:0] debug: comm point start listening 17 (-1 msec)
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: iterator module exit state is module_wait_reply
Dec 04 12:10:44 unbound[31914:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 12:10:44 unbound[31914:0] info: 0RDd mod2 rep dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: cache memory msg=69665 rrset=73368 infra=11669 val=66651 subnet=74504
Dec 04 12:10:44 unbound[31914:0] debug: answer cb
Dec 04 12:10:44 unbound[31914:0] debug: Incoming reply id = c888
Dec 04 12:10:44 unbound[31914:0] debug: Incoming reply addr = ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug: lookup size is 1 entries
Dec 04 12:10:44 unbound[31914:0] debug: received udp reply.
Dec 04 12:10:44 unbound[31914:0] debug: udp message[91:0] C8888180000100000001000005776F726B730000010001C00C0006000100000D9000380476306E30036E6963C00C0A686F73746D617374657206646F6E75747305656D61696C00638CDDC200001C20000003840012750000000E10
Dec 04 12:10:44 unbound[31914:0] debug: outnet handle udp reply
Dec 04 12:10:44 unbound[31914:0] debug: measured roundtrip at 11 msec
Dec 04 12:10:44 unbound[31914:0] debug: svcd callbacks start
Dec 04 12:10:44 unbound[31914:0] debug: worker svcd callback for qstate 0x55b51f4700
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: start
Dec 04 12:10:44 unbound[31914:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 04 12:10:44 unbound[31914:0] info: iterator operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: process_response: new external response event
Dec 04 12:10:44 unbound[31914:0] info: scrub for . NS IN
Dec 04 12:10:44 unbound[31914:0] info: response for dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] info: reply from <.> 192.33.4.12#53
Dec 04 12:10:44 unbound[31914:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 
;; QUESTION SECTION:
works.  IN      A

;; ANSWER SECTION:

;; AUTHORITY SECTION:
works.  3472    IN      SOA     v0n0.nic.works. hostmaster.donuts.email. 1670176194 7200 900 1209600 3600

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 91

Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 04 12:10:44 unbound[31914:0] info: query response was nodata ANSWER
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Dec 04 12:10:44 unbound[31914:0] info: processQueryTargets: dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 1
Dec 04 12:10:44 unbound[31914:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (19 result, 0 avail) cacheNS
Dec 04 12:10:44 unbound[31914:0] info:   a.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   m.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   l.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   k.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   j.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   i.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   h.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   g.root-servers.net. * A
Dec 04 12:10:44 unbound[31914:0] info:   f.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   e.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   d.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   c.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] info:   b.root-servers.net. * A AAAA
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:200::b port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:a8::e port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:500:2f::f port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    ip6 2001:503:ba3e::2:30 port 53 (len 28)
Dec 04 12:10:44 unbound[31914:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug: attempt to get extra 3 targets
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=239 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=234 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=233 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=196 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=110 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=242 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=302 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=234 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=187 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=230 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=200 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=187 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug:    rtt=159 REC_LAME
Dec 04 12:10:44 unbound[31914:0] debug: selrtt 360110
Dec 04 12:10:44 unbound[31914:0] debug: chase to recursion lame server
Dec 04 12:10:44 unbound[31914:0] debug: chase to dnssec lame server
Dec 04 12:10:44 unbound[31914:0] info: sending query: dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: sending to target: <.> 192.112.36.4#53
Dec 04 12:10:44 unbound[31914:0] debug: dnssec status: expected but lame_query anyway
Dec 04 12:10:44 unbound[31914:0] debug: EDNS lookup known=1 vs=0
Dec 04 12:10:44 unbound[31914:0] debug: serviced query UDP timeout=242 msec
Dec 04 12:10:44 unbound[31914:0] debug: inserted new pending reply id=8661
Dec 04 12:10:44 unbound[31914:0] debug: opened UDP if=0 port=27512
Dec 04 12:10:44 unbound[31914:0] debug: comm point start listening 18 (-1 msec)
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: iterator module exit state is module_wait_reply
Dec 04 12:10:44 unbound[31914:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 12:10:44 unbound[31914:0] info: 0RDd mod2 rep dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: cache memory msg=69912 rrset=73662 infra=11669 val=66651 subnet=74504
Dec 04 12:10:44 unbound[31914:0] debug: svcd callbacks end
Dec 04 12:10:44 unbound[31914:0] debug: close of port 46742
Dec 04 12:10:44 unbound[31914:0] debug: close fd 17
Dec 04 12:10:44 unbound[31914:0] debug: answer cb
Dec 04 12:10:44 unbound[31914:0] debug: Incoming reply id = 8661
Dec 04 12:10:44 unbound[31914:0] debug: Incoming reply addr = ip4 192.112.36.4 port 53 (len 16)
Dec 04 12:10:44 unbound[31914:0] debug: lookup size is 1 entries
Dec 04 12:10:44 unbound[31914:0] debug: received udp reply.
Dec 04 12:10:44 unbound[31914:0] debug: udp message[46:0] 86618180000100010000000006646E7373656305776F726B730000010001C00C0001000100000D910004052D6B58
Dec 04 12:10:44 unbound[31914:0] debug: outnet handle udp reply
Dec 04 12:10:44 unbound[31914:0] debug: measured roundtrip at 13 msec
Dec 04 12:10:44 unbound[31914:0] debug: svcd callbacks start
Dec 04 12:10:44 unbound[31914:0] debug: worker svcd callback for qstate 0x55b51f4700
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: start
Dec 04 12:10:44 unbound[31914:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 04 12:10:44 unbound[31914:0] info: iterator operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: process_response: new external response event
Dec 04 12:10:44 unbound[31914:0] info: scrub for . NS IN
Dec 04 12:10:44 unbound[31914:0] info: response for dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] info: reply from <.> 192.112.36.4#53
Dec 04 12:10:44 unbound[31914:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
dnssec.works.   IN      A

;; ANSWER SECTION:
dnssec.works.   3473    IN      A       5.45.107.88

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 46

Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 04 12:10:44 unbound[31914:0] info: query response was ANSWER
Dec 04 12:10:44 unbound[31914:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 04 12:10:44 unbound[31914:0] info: finishing processing for dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: iterator module exit state is module_finished
Dec 04 12:10:44 unbound[31914:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 04 12:10:44 unbound[31914:0] info: validator operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: validator: nextmodule returned
Dec 04 12:10:44 unbound[31914:0] debug: val handle processing q with state VAL_INIT_STATE
Dec 04 12:10:44 unbound[31914:0] debug: validator classification positive
Dec 04 12:10:44 unbound[31914:0] info: no signer, using dnssec.works. TYPE0 CLASS0
Dec 04 12:10:44 unbound[31914:0] debug: val handle processing q with state VAL_FINISHED_STATE
Dec 04 12:10:44 unbound[31914:0] info: validation failure <dnssec.works. A IN>: key for validation . is marked as invalid because of a previous validation failure <. DNSKEY IN>: no signatures from 192.5.5.241 for trust anchor . while building chain of trust
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: validator module exit state is module_finished
Dec 04 12:10:44 unbound[31914:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 04 12:10:44 unbound[31914:0] info: subnet operate: query dnssec.works. A IN
Dec 04 12:10:44 unbound[31914:0] debug: mesh_run: subnet module exit state is module_finished
Dec 04 12:10:44 unbound[31914:0] debug: query took 0.024525 sec
Dec 04 12:10:44 unbound[31914:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 04 12:10:44 unbound[31914:0] info: average recursion processing time 0.024525 sec
Dec 04 12:10:44 unbound[31914:0] info: histogram of recursion processing times
Dec 04 12:10:44 unbound[31914:0] info: [25%]=0 median[50%]=0 [75%]=0
Dec 04 12:10:44 unbound[31914:0] info: lower(secs) upper(secs) recursions
Dec 04 12:10:44 unbound[31914:0] info:    0.016384    0.032768 1
Dec 04 12:10:44 unbound[31914:0] debug: cache memory msg=70166 rrset=73906 infra=11669 val=66651 subnet=74504
Dec 04 12:10:44 unbound[31914:0] debug: svcd callbacks end
Dec 04 12:10:44 unbound[31914:0] debug: close of port 27512
Dec 04 12:10:44 unbound[31914:0] debug: close fd 18

@bigpcjunky here's the output for the trust anchor:

aamm19@pihole:~ $ sudo -u unbound unbound-anchor -v
/var/lib/unbound/root.key has content
success: the anchor is ok

Secondly, bit of a hack but is your Pi-hole set up to use Unbound, ie you're using localhost#5335 as the single upstream server? If so, try the dig command again but this time leave the port parameter off.

This will send it through Pi-hole which in turn will send it through Unbound anyway, and it will still fail. But now you can look at the Query Log and see how Pi-hole is interpreting the result. Maybe BOGUS or something else.

EDIT: I did have a bit more time than expected so I tried this ^ approach @chrislph
I made the change and strangely enough, I lost internet connection with the pi

aamm19@pihole:~ $ ping searx.com
PING searx.com (162.210.196.173) 56(84) bytes of data.
64 bytes from 162.210.196.173 (162.210.196.173): icmp_seq=2 ttl=52 time=49.6 ms
64 bytes from 162.210.196.173 (162.210.196.173): icmp_seq=3 ttl=52 time=49.1 ms
^C
--- searx.com ping statistics ---
3 packets transmitted, 2 received, 33.3333% packet loss, time 2010ms
rtt min/avg/max/mdev = 49.102/49.346/49.591/0.244 ms
aamm19@pihole:~ $ dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 37089
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 211 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sun Dec 04 12:38:46 CST 2022
;; MSG SIZE  rcvd: 41

#I changed the Upstream DNS Server from OpenDNS here to 127.0.0.1#5335

aamm19@pihole:~ $ ping searx.com
ping: searx.com: Temporary failure in name resolution
aamm19@pihole:~ $ dig dnssec.works @127.0.0.1    

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 50728
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Sun Dec 04 12:39:12 CST 2022
;; MSG SIZE  rcvd: 41
9

That seems expected because Unbound isn't resolving correctly. The reason for this test is that it will cause the queries to be routed through Pi-hole which will let you see them in Pi-hole's Query Log to see how the failure is being reported there.

10

As of now, it's been trying to query the debian ntp server but failing to do so

image
image994×794 136 KB

Needless to say, timedatectl now shows it's unsynched

aamm19@pihole:~ $ timedatectl
               Local time: Sun 2022-12-04 15:09:19 CST
           Universal time: Sun 2022-12-04 21:09:19 UTC
                 RTC time: n/a
                Time zone: America/Monterrey (CST, -0600)
System clock synchronized: no
              NTP service: active
          RTC in local TZ: no

This are the results on pihole.log

image
image1000×760 169 KB

11

My apologies, I forgot to add that Settings > DNS > Use DNSSEC needs to be ticked and then scroll down and click Save. This allows Pi-hole to show the DNSSEC results in the Query Log too. You'll then normally see SECURE where DNSSEC is available and working, or INSECURE where DNSSEC isn't available, or sometimes various errors like BOGUS showing that DNSSEC failed.

12

This did produce a different output, and some interesting things on it

image
image997×786 173 KB

query log:

image
image978×703 125 KB

192.180.100.100 is my computer

EDIT: 2 seconds after I post this, additional output appeared:

image
image987×791 157 KB

13

Hi,

Just sending an update on this whole issue, I've been sitting on it for a couple of days, still getting bogus responses on requests.

One piece of info that is showing on the unbound.log is the following
Dec 06 08:31:20 unbound[539:0] info: validation failure <dealer.spotify.com. A IN>: key for validation . is marked as invalid because of a previous validation failure <1.debian.pool.ntp.org. AAAA IN>: no signatures from 192.5.5.241 for trust anchor . while building chain of trust

Just posting it as to not let the thread die and also for ideas on what the issue could be.

14

This still looks like a timing issue.
DNSSEC validation would fail without correct time, and it would fail so already with the root servers.

Your recent log excerpts are consistent with that:

192.5.5.241 is one of the DNS root servers.
Your Pi-hole logs also suggest your system tries to acquire accurate time information through *.pool.ntp.org resources, but fails to resolve the respective domains, presumably due to incorrect timings.

What hardware do you run your Pi-hole on?
Does that feature a battery-backed RTC?

If not, consider fitting one.
If fitting an RTC is not an option, try configuring your Pi-hole host OS to use your router's IP as primary NTP server (provided your router supports that).
If that's also not an option, you could apply a dnsmasq custom configuration to forward requests for *.pool.ntp.org specfically to your router (e.g. server=/pool.ntp.org/<router_ip>), avoiding to involve unbound and DNSSEC validation.

15

Thanks for the response @Bucking_Horn,

To be completely honest, I'm still fairly new to the usage of Rasperries in general. I'll look into sourcing an RTC module if that'll make my life easier.

As for the option of using my router as an NTP server, is there a way I can verify this? I've logged into the router before but don't recall any option on time/ntp settings.

I'll look into the dnsmasq customization as well and keep posting any issues.

16

I cannot know that (unless it would be a FritzBox model similar to the one that I am using :wink: ).
Your router's documentaion and support channels should have the details.

In the meantime:

If you opt for that:

Create and edit a custom dnsmasq configuration file, e.g.

sudo nano /etc/dnsmasq.d/42-pool-ntp-org-forward.conf

Add the following lines

# forward requests for NTP server names to be resolved by my router's IP
server=/pool.ntp.org/192.168.0.1

Of course, replace 192.168.0.1 with your router's IPv4 address.

Then run a dnsmasq syntax check:

pihole-FTL dnsmasq-test

If ok, restart Pi-hole:

pihole restartdns
17

Hello internet.

I am back! Now with a DS3231 RTC ( Adafruit DS3231 Precision RTC Breakout) to test with!

I'll redo the whole setup later today along with research on how to configure the RTC and will provide an update.

18

Here's an update

I basically redid the whole setup focusing on setting up the RTC and doing a clean install of Pi-hole and unbound.

I followed the same steps as before and verified the trust anchor

aamm19@pihole:~ $ sudo -u unbound unbound-anchor -v
/var/lib/unbound/root.key has content
success: the anchor is ok

As well as configured the DNSSEC to be shown as per @chrislph's suggestion.

Current results:

aamm19@pihole:~ $ dig dnssec.works @127.0.0.1

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 38620
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; Query time: 139 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Dec 15 20:12:45 CST 2022
;; MSG SIZE  rcvd: 41

aamm19@pihole:~ $ dig dnssec.works @8.8.4.4

; <<>> DiG 9.16.33-Debian <<>> dnssec.works @8.8.4.4
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 64638
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;dnssec.works.                  IN      A

;; ANSWER SECTION:
dnssec.works.           2940    IN      A       5.45.107.88

;; Query time: 7 msec
;; SERVER: 8.8.4.4#53(8.8.4.4)
;; WHEN: Thu Dec 15 20:12:54 CST 2022
;; MSG SIZE  rcvd: 46

aamm19@pihole:~ $ timedatectl
               Local time: Thu 2022-12-15 20:13:07 CST
           Universal time: Fri 2022-12-16 02:13:07 UTC
                 RTC time: Fri 2022-12-16 02:13:07
                Time zone: America/Monterrey (CST, -0600)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

unbound.log (partial)

Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: start
Dec 15 20:19:18 unbound[15005:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 15 20:19:18 unbound[15005:0] info: iterator operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: process_response: new external response event
Dec 15 20:19:18 unbound[15005:0] info: scrub for . NS IN
Dec 15 20:19:18 unbound[15005:0] info: response for _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] info: reply from <.> 192.168.100.1#53
Dec 15 20:19:18 unbound[15005:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 
;; QUESTION SECTION:
_ta-4f66.	IN	NULL

;; ANSWER SECTION:

;; AUTHORITY SECTION:
.	3600	IN	SOA	a.root-servers.net. nstld.verisign-grs.com. 2022121501 1800 900 604800 86400

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 101

Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: query response was NXDOMAIN ANSWER
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: finishing processing for _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: iterator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: validator: nextmodule returned
Dec 15 20:19:18 unbound[15005:0] debug: not validating response, is valrec(validation recursion lookup)
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 15 20:19:18 unbound[15005:0] info: 0vRDCD mod2  . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: 1RDdc mod1 rep dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: cache memory msg=66817 rrset=67388 infra=8105 val=66368 subnet=74504
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks end
Dec 15 20:19:18 unbound[15005:0] debug: close of port 17371
Dec 15 20:19:18 unbound[15005:0] debug: close fd 14
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: outnettcp cb
Dec 15 20:19:18 unbound[15005:0] debug: outnet tcp pkt was written event
Dec 15 20:19:18 unbound[15005:0] debug: outnet tcp writes done, wait
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: comm point start listening 12 (60000 msec)
Dec 15 20:19:18 unbound[15005:0] debug: Reading tcp query of length 567
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: outnettcp cb
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks start
Dec 15 20:19:18 unbound[15005:0] debug: worker svcd callback for qstate 0x558d2739b0
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: start
Dec 15 20:19:18 unbound[15005:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 15 20:19:18 unbound[15005:0] info: iterator operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: process_response: new external response event
Dec 15 20:19:18 unbound[15005:0] info: scrub for . NS IN
Dec 15 20:19:18 unbound[15005:0] info: response for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: reply from <.> 192.168.100.1#53
Dec 15 20:19:18 unbound[15005:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
.	IN	DNSKEY

;; ANSWER SECTION:
.	86400	IN	DNSKEY	257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b}
.	86400	IN	DNSKEY	256 3 8 AwEAAeB54o2xvW6vY4qQZ0krDsEZCe6MsRWCqsXd4+cNJZMePnlV/xwDrIbbeH1SJzv742rOHzgAKM1/3SQHHSkoEIPx8XQdHAZBxfhaXl3e8c5WrE3aGXS5AeTWAkt85ccqWgKyitxjFmJEOol0BqS2xueltaDwgWcC10nPUY+y5l/kTOYyptYQS4gg1uJNXIob/R1XIEJ10ZCurkYqZxgqyHc7tZv09N23o9rnGdjnYiArH7FjlXD8Rvjde8YWkmfdbCEWnchrnxDK8KV2/ZvBpG/WYnRKXYPUceGCw59OJdJ5M7utkm547RB3eEd8CVVhbXopZlsKq3GCrBwaIVe9ci0= ;{id = 18733 (zsk), size = 2048b}

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 567

Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: query response was ANSWER
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: finishing processing for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: iterator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: validator: nextmodule returned
Dec 15 20:19:18 unbound[15005:0] debug: not validating response, is valrec(validation recursion lookup)
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] info: validator: inform_super, sub is . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: super is dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] info: autotrust process for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: rrset failed to verify due to a lack of signatures
Dec 15 20:19:18 unbound[15005:0] debug: Failed to match any usable anchor to a DNSKEY.
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: validate DNSKEY with anchor: sec_status_bogus
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: dnskey did not verify.
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: write to disk: /var/lib/unbound/root.key.15005-0-558cc6da30
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: replaced /var/lib/unbound/root.key
Dec 15 20:19:18 unbound[15005:0] debug: rrset failed to verify due to a lack of signatures
Dec 15 20:19:18 unbound[15005:0] debug: Failed to match any usable anchor to a DNSKEY.
Dec 15 20:19:18 unbound[15005:0] info: validate keys with anchor(DS): sec_status_bogus
Dec 15 20:19:18 unbound[15005:0] info: failed to prime trust anchor -- DNSKEY rrset is not secure . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Dec 15 20:19:18 unbound[15005:0] info: Could not establish a chain of trust to keys for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: val handle processing q with state VAL_FINISHED_STATE
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: query took 0.150888 sec
Dec 15 20:19:18 unbound[15005:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 15 20:19:18 unbound[15005:0] info: average recursion processing time 0.150888 sec
Dec 15 20:19:18 unbound[15005:0] info: histogram of recursion processing times
Dec 15 20:19:18 unbound[15005:0] info: [25%]=0 median[50%]=0 [75%]=0
Dec 15 20:19:18 unbound[15005:0] info: lower(secs) upper(secs) recursions
Dec 15 20:19:18 unbound[15005:0] info:    0.131072    0.262144 1
Dec 15 20:19:18 unbound[15005:0] debug: cache memory msg=66817 rrset=67388 infra=8105 val=66537 subnet=74504
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks end
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: comm point start listening 12 (60000 msec)

Pi-hole Query Log:

image
image979×485 97.3 KB

I might be missing any configuration or steps I did before so if you see anything different just let me know and I'll keep updating.

19

Hi @aamm19 did you get anywhere with this? Is it still behaving the same? It's clearly something to do with the section below – without the chain of trust from the root upwards, the result is flagged as BOGUS, hence Pi-hole reporting as "BOGUS (refused upstream)" where "upstream" in this case is simply a reference to Unbound.

But you've sorted your system clock and it's correct (from your paste) and your root file was also sorted, so I'm not sure how to interpret what Unbound is doing. I'm wondering if it's a permissions issue for the root key or something like that.

debug: autotrust: validate DNSKEY with anchor: sec_status_bogus
debug: autotrust: dnskey did not verify.
debug: autotrust: write to disk: /var/lib/unbound/root.key.15005-0-558cc6da30
debug: autotrust: replaced /var/lib/unbound/root.key
debug: rrset failed to verify due to a lack of signatures
debug: Failed to match any usable anchor to a DNSKEY.
20

Hi @chrislph, thanks for the follow-up! I did some testing a bit after that and disconnected the Raspberry-Pi for a couple of hours (both power and internet), but the clock seems to keeps getting the time off by a margin.

I'll try and repeat the setup and run through the motions these days to see if I can get this issue sorted out. It keeps bugging me something you pointed out towards the Authenticated Data part of the dig requests, It might even be blacklisting because of the number of requests or something (hopefully not haha)

Will update once I've finished the setup.