Unbound not working with pi-hole

[Joulinar]

@WarHawk

Ah so his Unbound service isn’t starting

the service is starting but Unbound is not able to connect to root DNS server

[Joulinar]

@xMike

root@Pi-hole:~# journalctl -u unbound. Service
Failed to add match 'Service': Invalid argument

Ahhh typo. Try following

journalctl -u unbound.service

[xMike]

root@Pi-hole:~# journalctl -u unbound.service
-- Journal begins at Mon 2022-09-26 03:16:57 PDT, ends at Mon 2022-09-26 03:20:01 PDT. --
Sep 26 03:16:58 Pi-hole systemd[1]: Starting Unbound DNS server...
Sep 26 03:16:58 Pi-hole unbound[409]: [409:0] notice: init module 0: subnet
Sep 26 03:16:58 Pi-hole unbound[409]: [409:0] notice: init module 1: validator
Sep 26 03:16:58 Pi-hole unbound[409]: [409:0] notice: init module 2: iterator
Sep 26 03:16:59 Pi-hole systemd[1]: Started Unbound DNS server.
Sep 26 03:16:59 Pi-hole unbound[409]: [409:0] info: start of service (unbound 1.13.1).
Sep 26 03:16:59 Pi-hole unbound[409]: [409:0] info: resolving . DNSKEY IN
Sep 26 03:16:59 Pi-hole unbound[409]: [409:0] info: priming . IN NS
Sep 26 03:17:02 Pi-hole unbound[409]: [409:0] info: Capsforid: timeouts, starting fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.97.190.53#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.112.36.4#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.41.0.4#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.97.190.53#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 199.7.83.42#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 199.7.83.42#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 199.9.14.201#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.112.36.4#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 199.9.14.201#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.33.4.12#53
Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback

[Jappe]

There is also another unbound instance running on oort 8953, which is not default behavior?;

[Joulinar]

@Jappe

There is also another unbound instance running on oort 8953, which is not default behavior?

This is fine and expected.

[Joulinar]

at least we changed from

Sep 26 02:01:21 Pi-hole unbound[1074]: [1074:0] info: query response REC_LAME: recursive but not authoritative server
Sep 26 02:01:21 Pi-hole unbound[1074]: [1074:0] info: mark as REC_LAME

to

Sep 26 03:17:07 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback

Still unbound seems to have challanges with connecting to the root DNS server.

I guess dig is still failing?

dig @127.0.0.1 -p 5335 google.com

[xMike]

oh man, i can’t make heads or tails with all this output, lol
way past my head, haha
props for everyone else who can understand it

root@Pi-hole:~# dig @127.0.0.1 -p 5335 google.com

; <<>> DiG 9.16.33-Debian <<>> @127.0.0.1 -p 5335 google.com
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 32743
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

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

;; Query time: 500 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Mon Sep 26 03:29:09 PDT 2022
;; MSG SIZE  rcvd: 39

[Joulinar]

@xMike

`;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 32743`

That’s the important line as status=SERVFAIL

It has something to do with the Capsforid: timeouts message on the log. I need to check where this is coming from.

[Joulinar]

let’s try to increase the log level once more. This should enable the debug mode.

G_CONFIG_INJECT '        verbosity:' '        verbosity:3' /etc/unbound/unbound.conf.d/dietpi.conf

Reboot the system and check the logs

journalctl -u unbound.service

[xMike]

i believe in you

root@Pi-hole:~# journalctl -u unbound.service
-- Journal begins at Mon 2022-09-26 03:55:03 PDT, ends at Mon 2022-09-26 03:56:26 PDT. --
Sep 26 03:55:04 Pi-hole systemd[1]: Starting Unbound DNS server...
Sep 26 03:55:04 Pi-hole unbound[409]: [1664189704] unbound[409:0] debug: switching log to syslog
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: chdir to /etc/unbound
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: drop user privileges, run as unbound
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: module config: "subnetcache validator iterator"
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] notice: init module 0: subnet
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: subnet: option registered (8)
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] notice: init module 1: validator
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] notice: init module 2: iterator
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: target fetch policy for level 0 is 3
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: target fetch policy for level 1 is 2
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: target fetch policy for level 2 is 1
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: target fetch policy for level 3 is 0
Sep 26 03:55:04 Pi-hole unbound[409]: [409:0] debug: target fetch policy for level 4 is 0
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: Reading root hints from /var/lib/unbound/root.hints
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=66368 subnet=74504
Sep 26 03:55:05 Pi-hole systemd[1]: Started Unbound DNS server.
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: start of service (unbound 1.13.1).
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: subnet operate: query . DNSKEY IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: validator operate: query . DNSKEY IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: resolving . DNSKEY IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: priming . IN NS
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 202.12.27.33#53
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 199.9.14.201#53
Sep 26 03:55:05 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=8547 val=66368 subnet=74504
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 202.12.27.33#53
Sep 26 03:55:06 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=8547 val=66368 subnet=74504
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.58.128.30#53
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=8844 val=66368 subnet=74504
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: Capsforid: timeouts, starting fallback
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.58.128.30#53
Sep 26 03:55:08 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=8844 val=66368 subnet=74504
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 199.7.91.13#53
Sep 26 03:55:10 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=9141 val=66368 subnet=74504
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.112.36.4#53
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=9438 val=66368 subnet=74504
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.112.36.4#53
Sep 26 03:55:11 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=9438 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.112.36.4#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=9735 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=9735 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.33.4.12#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10032 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.33.4.12#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10032 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10032 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 198.97.190.53#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10329 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.97.190.53#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.36.148.17#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10626 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.36.148.17#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10626 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 192.5.5.241#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 198.41.0.4#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10923 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.41.0.4#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: sending query: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: sending to target: <.> 198.41.0.4#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10923 val=66368 subnet=74504
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: response for . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: reply from <.> 198.41.0.4#53
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: Capsforid: reply is equal. go to next fallback
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: request . has exceeded the maximum number of glue fetches 17 to a single delegation point
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: return error response SERVFAIL
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: validator operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: subnet operate: query . NS IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: iterator operate: query . DNSKEY IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: processQueryTargets: . DNSKEY IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: Failed to get a delegation, giving up
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: return error response SERVFAIL
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: validator operate: query . DNSKEY IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] info: subnet operate: query . DNSKEY IN
Sep 26 03:55:13 Pi-hole unbound[409]: [409:0] debug: cache memory msg=66072 rrset=66072 infra=10923 val=66368 subnet=74504

[Joulinar]

sorry for digging around but I’m still not sure why Unbound has issues to connect to root DNS servers.

Let’s try to increase debug level to the highest level 5.

G_CONFIG_INJECT '        verbosity:' '        verbosity:5' /etc/unbound/unbound.conf.d/dietpi.conf

Reboot and check logs again

journalctl -u unbound.service

and we could check the root DNS server directly if they are reachable

dig @202.12.27.33 google.com

[xMike]

oh no, thank you for helping

the log was too big for me to paste it all, but the dig command worked

Body is limited to 32000 characters; you entered 184035

root@Pi-hole:~# dig @202.12.27.33 google.com

; <<>> DiG 9.16.33-Debian <<>> @202.12.27.33 google.com
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 45073
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;google.com.                    IN      A

;; ANSWER SECTION:
google.com.             258     IN      A       142.251.211.238

;; Query time: 12 msec
;; SERVER: 202.12.27.33#53(202.12.27.33)
;; WHEN: Mon Sep 26 04:54:24 PDT 2022
;; MSG SIZE  rcvd: 55

[Joulinar]

@xMike

the log was too big for me to paste it all, but the dig command worked

you could export the journalctl into a log file and attach it to the post

journalctl -u unbound.service > /tmp/log.txt

[xMike]

log attached!
i’m going to sleep now, 5:44 am
thanks for all your help so far! hopefully we can figure this out
log.txt (189.1 KB)

[Joulinar]

Honestly I’m still not sure what the issue is exactly. There are quite some time outs on the debug log. Something seems to block communication betweem Unbound and root DNS server.

Maybe @MichaIng or @trendy have an idea.

For testing, we could try to adjust DNS forward zone to point to Cloudflare and Quad9. Let’s see if this might be working. At least we could check the general functionality.

cat << '_EOF_' > /etc/unbound/unbound.conf.d/dietpi-forward.conf
# Adding own forward-zone
forward-zone:
name: "."
## Cloudflare
forward-addr: 1.1.1.1@53#cloudflare-dns.com
forward-addr: 1.0.0.1@53#cloudflare-dns.com
## Quad9
forward-addr: 9.9.9.9@53#dns.quad9.net
forward-addr: 149.112.112.112@53#dns.quad9.net
_EOF_

restart service and perform a test

systemctl restart unbound
dig @127.0.0.1 -p 5335 google.com

[xMike]

damn, stumping us both

root@Pi-hole:~# cat << '_EOF_' > /etc/unbound/unbound.conf.d/dietpi-forward.conf
> # Adding own forward-zone
112@53#> forward-zone:
> name: "."
> ## Cloudflare
> forward-addr: 1.1.1.1@53#cloudflare-dns.com
> forward-addr: 1.0.0.1@53#cloudflare-dns.com
> ## Quad9
> forward-addr: 9.9.9.9@53#dns.quad9.net
> forward-addr: 149.112.112.112@53#dns.quad9.net
> _EOF_
root@Pi-hole:~# systemctl restart unbound
root@Pi-hole:~# dig @127.0.0.1 -p 5335 google.com

; <<>> DiG 9.16.33-Debian <<>> @127.0.0.1 -p 5335 google.com
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 39645
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

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

;; Query time: 16 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Mon Sep 26 15:04:29 PDT 2022
;; MSG SIZE  rcvd: 39

[WarHawk]

worse comes to worse, might also try uninstalling the dietpi package…and manually install/configure (kinda defeats the purpose of using the easy to install package system though)

I know when I put it on a debian 11 VM in PROXMOX on my network as a test…I followed this walkthru and it worked like a champ with NO issues…1st try
unbound - Pi-hole documentation

[xMike]

ah, yeah. i actually installed it on a vps (ubuntu 20.04) earlier which worked fine with the same documentation, but for some reason i couldn’t get it to work with dietpi

[Joulinar]

@xMike

i actually installed it on a vps

I guess the system was located outside of your network at a Cloud Server provider? Correct? This makes a difference as network environment is completely different.

[xMike]

correct! so it’s not a fair comparison for dietpi since there’s different variables at play