Very strange or very stupid? unbound problem. #not resolvconf_resolvers

Hi everybody,
It's been a looong time since i've written in a forum for infos thanks to the many guides online with answers for every thinkable topic, but here i am.

I'll explain briefly what lead me where i am now, i'll post some code hoping it's a stupid error ( no doubt about it).

TL;DR:
Unbound recursive DNS doesn't work but i did already disabled and deleted resolvconf.. why?

Short History:
After a bit of trouble installing and configuring piHole and a bit of time passed I found out about unbound and his DoT capability. I had to have it, i thought.
I had some trouble with my DoT config so i wondered about various networking .conf files - never a good thing to do - but after a couple days and lots of guides i did manage to understand enough to make it work with no problems at all.
( At this DoT step come to help the guides about the resolvconf_resolver which i disabled and removed )

After a week i found out about the recursive DNS possibilty: the real deal. I had to have it.
So backed up my pihole.conf and made a new one exactly a copy of :star2:The Guide :star2: and.... here comes the problem :

It should work as it is but mine doesn't.
So here comes all the .conf files i think i touched since my first unbound install + unbound logs.

Unbound conf:

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/pihole.conf:server:
/etc/unbound/unbound.conf.d/pihole.conf:     logfile: "/var/log/unbound/unbound.log"
/etc/unbound/unbound.conf.d/pihole.conf:    verbosity: 3
/etc/unbound/unbound.conf.d/pihole.conf:    interface: 127.0.0.1
/etc/unbound/unbound.conf.d/pihole.conf:    port: 5335
/etc/unbound/unbound.conf.d/pihole.conf:    do-ip4: yes
/etc/unbound/unbound.conf.d/pihole.conf:    do-udp: yes
/etc/unbound/unbound.conf.d/pihole.conf:    do-tcp: yes
/etc/unbound/unbound.conf.d/pihole.conf:    do-ip6: no
/etc/unbound/unbound.conf.d/pihole.conf:    prefer-ip6: no
/etc/unbound/unbound.conf.d/pihole.conf:    harden-glue: yes
/etc/unbound/unbound.conf.d/pihole.conf:    harden-dnssec-stripped: yes
/etc/unbound/unbound.conf.d/pihole.conf:    use-caps-for-id: no
/etc/unbound/unbound.conf.d/pihole.conf:    edns-buffer-size: 1472
/etc/unbound/unbound.conf.d/pihole.conf:    prefetch: yes
/etc/unbound/unbound.conf.d/pihole.conf:    num-threads: 1
/etc/unbound/unbound.conf.d/pihole.conf:    so-rcvbuf: 1m
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: 192.168.0.0/16
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: 169.254.0.0/16
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: 172.16.0.0/12
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: 10.0.0.0/8
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: fd00::/8
/etc/unbound/unbound.conf.d/pihole.conf:    private-address: fe80::/10

dhcpd.conf

 sudo grep -v '#\|^$' -R /etc/dhcpcd.conf
hostname
clientid
persistent
option rapid_commit
option domain_name_servers, domain_name, domain_search, host_name
option classless_static_routes
option interface_mtu
require dhcp_server_identifier
slaac private
interface eth0
        static ip_address=192.168.1.3/24
        static routers=192.168.1.1
        static domain_name_servers=9.9.9.9, 1.1.1.1, 8.8.8.8; 

Resolvconf.conf

sudo grep -v '#\|^$' -R /etc/resolvconf.conf
resolv_conf=/etc/resolv.conf
name_servers=9.9.9.9, 1.1.1.1, 8.8.8.8;
dnsmasq_resolv=/var/run/dnsmasq/resolv.conf
pdnsd_conf=/etc/pdnsd.conf

dig google.com

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

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

;; Query time: 55 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Mon Nov 14 21:51:29 CET 2022
;; MSG SIZE  rcvd: 39

dig sigok

dig sigok.verteiltesysteme.net @127.0.0.1 -p 5335

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

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1472
;; QUESTION SECTION:
;sigok.verteiltesysteme.net.	IN	A

;; Query time: 51 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Mon Nov 14 21:49:53 CET 2022
;; MSG SIZE  rcvd: 55

nslookup

nslookup google.com
Server:		9.9.9.9
Address:	9.9.9.9#53

Non-authoritative answer:
Name:	google.com
Address: 142.250.184.78
Name:	google.com
Address: 2a00:1450:4002:405::200e

An extract from V2 Log unbound querying sigok and roots i think

[1668459476] unbound[10150:0] info: reply from <.> 202.12.27.33#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459476] unbound[10150:0] info: response for . NS IN
[1668459476] unbound[10150:0] info: reply from <.> 199.7.83.42#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459476] unbound[10150:0] info: response for . NS IN
[1668459476] unbound[10150:0] info: reply from <.> 198.97.190.53#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459476] unbound[10150:0] info: response for . NS IN
[1668459476] unbound[10150:0] info: reply from <.> 199.7.83.42#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459476] unbound[10150:0] info: response for . NS IN
[1668459476] unbound[10150:0] info: reply from <.> 192.203.230.10#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459476] unbound[10150:0] info: response for . NS IN
[1668459476] unbound[10150:0] info: reply from <.> 198.41.0.4#53
[1668459476] unbound[10150:0] info: query response was THROWAWAY
[1668459520] unbound[10150:0] info: resolving sigok.verteiltesysteme.net. A IN
[1668459520] unbound[10150:0] info: priming . IN NS
[1668459520] unbound[10150:0] info: response for . NS IN
[1668459520] unbound[10150:0] info: reply from <.> 192.112.36.4#53
[1668459520] unbound[10150:0] info: query response was THROWAWAY
[1668459520] unbound[10150:0] info: response for . NS IN
[1668459520] unbound[10150:0] info: reply from <.> 192.33.4.12#53
[1668459520] unbound[10150:0] info: query response was THROWAWAY
[1668459520] unbound[10150:0] info: response for . NS IN
[1668459520] unbound[10150:0] info: reply from <.> 202.12.27.33#53
[1668459520] unbound[10150:0] info: query response was THROWAWAY
[1668459520] unbound[10150:0] info: response for . NS IN
[1668459520] unbound[10150:0] info: reply from <.> 202.12.27.33#53
[1668459520] unbound[10150:0] info: query response was THROWAWAY

An extract of unbound Log V3 querying sigok etc.

1668459638] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668459638] unbound[10199:0] info: iterator operate: query . NS IN
[1668459638] unbound[10199:0] info: response for . NS IN
[1668459638] unbound[10199:0] info: reply from <.> 198.41.0.4#53
[1668459638] unbound[10199:0] info: query response was THROWAWAY
[1668459638] unbound[10199:0] info: processQueryTargets: . NS IN
[1668459638] unbound[10199:0] info: sending query: . NS IN
[1668459638] unbound[10199:0] debug: sending to target: <.> 202.12.27.33#53
[1668459638] unbound[10199:0] debug: cache memory msg=66072 rrset=66072 infra=11669 val=66368 subnet=74504
[1668459638] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668459638] unbound[10199:0] info: iterator operate: query . NS IN
[1668459638] unbound[10199:0] info: response for . NS IN
[1668459638] unbound[10199:0] info: reply from <.> 202.12.27.33#53
[1668459638] unbound[10199:0] info: query response was THROWAWAY
[1668459638] unbound[10199:0] info: processQueryTargets: . NS IN
[1668459638] unbound[10199:0] debug: request has exceeded the maximum number of sends with 33
[1668459638] unbound[10199:0] debug: return error response SERVFAIL
[1668459638] unbound[10199:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
[1668459638] unbound[10199:0] info: validator operate: query . NS IN
[1668459638] unbound[10199:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1668459638] unbound[10199:0] info: subnet operate: query . NS IN
[1668459638] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
[1668459638] unbound[10199:0] info: iterator operate: query . DNSKEY IN
[1668459638] unbound[10199:0] info: processQueryTargets: . DNSKEY IN
[1668459638] unbound[10199:0] debug: Failed to get a delegation, giving up
[1668459638] unbound[10199:0] debug: return error response SERVFAIL
[1668459638] unbound[10199:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1668459638] unbound[10199:0] info: validator operate: query . DNSKEY IN
[1668459638] unbound[10199:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1668459638] unbound[10199:0] info: subnet operate: query . DNSKEY IN
[1668459638] unbound[10199:0] debug: cache memory msg=66072 rrset=66072 infra=11669 val=66368 subnet=74504
[1668459641] unbound[10199:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
[1668459641] unbound[10199:0] info: subnet operate: query sigok.verteiltesysteme.net. A IN
[1668459641] unbound[10199:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1668459641] unbound[10199:0] info: validator operate: query sigok.verteiltesysteme.net. A IN
[1668459641] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1668459641] unbound[10199:0] info: resolving sigok.verteiltesysteme.net. A IN
[1668459641] unbound[10199:0] info: priming . IN NS
[1668459641] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1668459641] unbound[10199:0] info: iterator operate: query . NS IN
[1668459641] unbound[10199:0] info: processQueryTargets: . NS IN
[1668459641] unbound[10199:0] info: sending query: . NS IN
[1668459641] unbound[10199:0] debug: sending to target: <.> 199.9.14.201#53
[1668459641] unbound[10199:0] debug: cache memory msg=66072 rrset=66072 infra=11669 val=66368 subnet=74504
[1668459641] unbound[10199:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668459641] unbound[10199:0] info: iterator operate: query . NS IN
[1668459641] unbound[10199:0] info: response for . NS IN
[1668459641] unbound[10199:0] info: reply from <.> 199.9.14.201#53
[1668459641] unbound[10199:0] info: query response was THROWAWAY
[1668459641] unbound[10199:0] info: processQueryTargets: . NS IN

I think the THROWAWAY response is an indication that the DNS data chain can't be trusted. You probably need to run unbound-anchor or the stat command to see if unbound has the right permissions to update /var/lib/unbound/root.key.

Unbound needs to use root.hints and the root.key to prime it's DNS trust chain while /etc/resolv.conf is set to a 3rd party DNS server like Google. Once the trust chain has been primed you can update /etc/resolv.conf to point to 127.0.0.1 so Unbound can do it's thing as a recursive caching DNSSEC server.

1 Like

Handy tip for Unbound log – add the following into /etc/unbound/unbound.conf.d/pihole.conf

log-time-ascii: yes

This logs timestamps as human-readable, changing this

[1668459476] unbound[10150:0] info: query response was THROWAWAY

to this

Nov 14 20:57:56 unbound[10150:0] info: query response was THROWAWAY

1 Like

That domain does not seem to be available anymore.
Use the DNSSEC test servers as updated in our guide:

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

Note that DNSSEC requires accurate time information.
The times from your dig results and logs do not seem to match - one instance I've checked they differ for about 10 minutes.
This may just be a result of extracting logs for a different time frame, but still:
You want to verify that your unbound host machine has correct time and time zone information.

1 Like

First thanks you all for the fast answers i read them and tried them this morning before work, and now i have the time to write you back.

*First i changed the conf as chrislph said. Thanks you.

*Second i tried what bigpcjunky suggested. So i checked the root.key and joyously saw it was root:root.

sudo chown unbound:unbound -R root.key 

no errors there, so
resolvconf.conf

#nameserver=9.9.9....... etc
nameserver=127.0.0.1;   

(shouldn't i add the port #5335?) <-- maybe i read in the guide that resolvconf doesn't take ports but not sure.

Anyway then I did:

unbound-anchor -a root.key

And no error there so it can write it.

*Third as per #Bucking_Horn :
Checked and updated my timezone just in case with raspi-config ( updated everything including wifi zone )
Now finally the reboot. And....

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: 46896
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

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

;; Query time: 51 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Tue Nov 15 19:34:26 CET 2022
;; MSG SIZE  rcvd: 41

dig google.com @127.0.0.1 -p 5335

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

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

;; Query time: 43 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Tue Nov 15 19:34:23 CET 2022
;; MSG SIZE  rcvd: 39

Nothing. Again. This time i seriously believed it would be the one.
Just FYI i'm gonna copy another V2 log ( even if it's almost the same as all the others )

Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 199.9.14.201#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 199.9.14.201#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 192.36.148.17#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 192.5.5.241#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 192.36.148.17#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 198.41.0.4#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:19 unbound[574:0] info: response for . NS IN
Nov 15 19:51:19 unbound[574:0] info: reply from <.> 199.7.83.42#53
Nov 15 19:51:19 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:32 unbound[574:0] info: resolving dnssec.works. A IN
Nov 15 19:51:32 unbound[574:0] info: priming . IN NS
Nov 15 19:51:32 unbound[574:0] info: response for . NS IN
Nov 15 19:51:32 unbound[574:0] info: reply from <.> 192.36.148.17#53
Nov 15 19:51:32 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:32 unbound[574:0] info: response for . NS IN
Nov 15 19:51:32 unbound[574:0] info: reply from <.> 198.41.0.4#53
Nov 15 19:51:32 unbound[574:0] info: query response was THROWAWAY
Nov 15 19:51:32 unbound[574:0] info: response for . NS IN
Nov 15 19:51:32 unbound[574:0] info: reply from <.> 192.112.36.4#53

Have i messed up or misunderstood something?
Is this really complicated after all?

PS: The time between the commands and the logs was because V3 logs are a freaking mess, even more so with nano.

Let's try to find out if DNSSEC validation is involved here.

Run from your Pi-hole host machine, what's the output of:

delv dnssec.works @127.0.0.1 -p 5335
1 Like
delv dnssec.works @127.0.0.1 -p 5335
;; resolution failed: SERVFAIL

So resolution fails before DNSSEC validation kicks in.

Let's search for explicit errors in your logs next:

grep -n error /var/log/unbound/unbound.log

And if you didn't do that already, you should point your Pi-hole to use some public DNS resolvers instead of unbound. This would limit unbound's log to be filled only by those requests you manually send to Pi-hole.

1 Like

Pi-hole public DNS done.
and here is the grep

grep -n error /var/log/unbound/unbound.log
541:[1668459638] unbound[10199:0] debug: return error response SERVFAIL
550:[1668459638] unbound[10199:0] debug: return error response SERVFAIL
864:[1668459641] unbound[10199:0] debug: return error response SERVFAIL
873:[1668459641] unbound[10199:0] debug: return error response SERVFAIL
1647:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1648:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1649:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1650:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1651:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1652:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1653:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1654:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1655:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1656:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1657:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1658:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1659:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1660:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1661:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1662:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1663:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1664:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1665:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1666:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1667:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1668:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1669:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1670:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1671:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1672:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1673:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1674:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1675:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1676:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1677:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1678:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1679:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1680:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1681:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1682:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1683:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1684:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1685:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1686:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1687:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1688:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1689:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1690:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1691:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1692:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1693:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1694:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1695:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1696:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1697:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1698:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1699:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1700:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1701:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1702:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1703:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1704:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1705:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1706:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1707:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1708:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1709:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1710:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1711:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1714:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1715:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1716:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1717:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1718:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1719:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1720:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1721:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1722:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1723:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1724:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1725:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1726:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1729:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1730:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1731:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1732:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1733:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1734:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1735:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1736:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1737:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1738:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1739:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1740:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1741:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1744:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1745:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1746:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1747:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1748:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1749:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1750:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1751:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1752:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1753:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1754:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1755:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1756:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1759:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1760:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1761:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1762:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1763:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1764:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1765:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1766:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1767:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1768:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53
1769:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1770:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1771:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1774:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.83.42 port 53
1775:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.97.190.53 port 53
1776:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.112.36.4 port 53
1777:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.5.5.241 port 53
1778:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 202.12.27.33 port 53
1779:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.7.91.13 port 53
1780:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.58.128.30 port 53
1781:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.33.4.12 port 53
1782:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 193.0.14.129 port 53
1783:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.203.230.10 port 53
1784:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 198.41.0.4 port 53
1785:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 199.9.14.201 port 53
1786:Nov 15 19:44:33 unbound[574:0] info: error sending query to auth server 192.36.148.17 port 53

Edit: now that i think of it... port 53 is the port that pihole uses and a port that docker use? because i have docker installed too. Or is it only the case if i install pihole in docker?

It's expected and correct that unbound tries upstream resolution via port 53.

Port 53 is the port that any DNS server uses. There's only reason for concern if multiple processes on the same machine would fight for control over port 53.

Your unbound.log shows that sending requests to root servers is failing consistently, e.g. for 199.7.83.42.

What's the result of contacting that root server directly?
Please run the following commands from your unbound host machine:

dig +notcp @199.7.83.4
dig +tcp @199.7.83.4
1 Like
dig +notcp @199.7.83.4

; <<>> DiG 9.16.33-Debian <<>> +notcp @199.7.83.4
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 19138
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 13, AUTHORITY: 0, ADDITIONAL: 27

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;.				IN	NS

;; ANSWER SECTION:
.			517127	IN	NS	a.root-servers.net.
.			517127	IN	NS	b.root-servers.net.
.			517127	IN	NS	c.root-servers.net.
.			517127	IN	NS	d.root-servers.net.
.			517127	IN	NS	e.root-servers.net.
.			517127	IN	NS	f.root-servers.net.
.			517127	IN	NS	g.root-servers.net.
.			517127	IN	NS	h.root-servers.net.
.			517127	IN	NS	i.root-servers.net.
.			517127	IN	NS	j.root-servers.net.
.			517127	IN	NS	k.root-servers.net.
.			517127	IN	NS	l.root-servers.net.
.			517127	IN	NS	m.root-servers.net.

;; ADDITIONAL SECTION:
a.root-servers.net.	517127	IN	A	198.41.0.4
a.root-servers.net.	517127	IN	AAAA	2001:503:ba3e::2:30
b.root-servers.net.	517127	IN	A	199.9.14.201
b.root-servers.net.	517127	IN	AAAA	2001:500:200::b
c.root-servers.net.	517127	IN	A	192.33.4.12
c.root-servers.net.	517127	IN	AAAA	2001:500:2::c
d.root-servers.net.	517127	IN	A	199.7.91.13
d.root-servers.net.	517127	IN	AAAA	2001:500:2d::d
e.root-servers.net.	517127	IN	A	192.203.230.10
e.root-servers.net.	517127	IN	AAAA	2001:500:a8::e
f.root-servers.net.	517127	IN	A	192.5.5.241
f.root-servers.net.	517127	IN	AAAA	2001:500:2f::f
g.root-servers.net.	517127	IN	A	192.112.36.4
g.root-servers.net.	517127	IN	AAAA	2001:500:12::d0d
h.root-servers.net.	517127	IN	A	198.97.190.53
h.root-servers.net.	517127	IN	AAAA	2001:500:1::53
i.root-servers.net.	517127	IN	A	192.36.148.17
i.root-servers.net.	517127	IN	AAAA	2001:7fe::53
j.root-servers.net.	517127	IN	A	192.58.128.30
j.root-servers.net.	517127	IN	AAAA	2001:503:c27::2:30
k.root-servers.net.	517127	IN	A	193.0.14.129
k.root-servers.net.	517127	IN	AAAA	2001:7fd::1
l.root-servers.net.	517127	IN	A	199.7.83.42
l.root-servers.net.	517127	IN	AAAA	2001:500:9f::42
m.root-servers.net.	517127	IN	A	202.12.27.33
m.root-servers.net.	517127	IN	AAAA	2001:dc3::35

;; Query time: 23 msec
;; SERVER: 199.7.83.4#53(199.7.83.4)
;; WHEN: Tue Nov 15 22:50:44 CET 2022
;; MSG SIZE  rcvd: 811
dig +tcp @199.7.83.4

; <<>> DiG 9.16.33-Debian <<>> +tcp @199.7.83.4
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 49584
;; flags: qr rd ra; QUERY: 1, ANSWER: 13, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1220
; COOKIE: 6733c2a91b7159bea1cc869b637409f86b54b0fecd497505 (good)
;; QUESTION SECTION:
;.				IN	NS

;; ANSWER SECTION:
.			244924	IN	NS	e.root-servers.net.
.			244924	IN	NS	i.root-servers.net.
.			244924	IN	NS	h.root-servers.net.
.			244924	IN	NS	k.root-servers.net.
.			244924	IN	NS	f.root-servers.net.
.			244924	IN	NS	b.root-servers.net.
.			244924	IN	NS	j.root-servers.net.
.			244924	IN	NS	g.root-servers.net.
.			244924	IN	NS	d.root-servers.net.
.			244924	IN	NS	m.root-servers.net.
.			244924	IN	NS	l.root-servers.net.
.			244924	IN	NS	a.root-servers.net.
.			244924	IN	NS	c.root-servers.net.

;; Query time: 47 msec
;; SERVER: 199.7.83.4#53(199.7.83.4)
;; WHEN: Tue Nov 15 22:51:52 CET 2022
;; MSG SIZE  rcvd: 267

Both commands did succeed:
dig is able to talk to that root server directly, so there's no issue with your upstream network connectivity.

That suggests that your issue lies indeed with your unbound configuration.
I'm running out of ideas for possible causes, though.

There's one potential hint left:

Your pihole.conf has this line:

However, our guide suggests to use edns-buffer-size: 1232.

You could try to see if adopting that value would make any difference.

1 Like

Unfortunately neither this worked. Maybe something has bugged somewhere in the deepest and remote location inside my poor raspbi.
Anyway at this point i'll wait a couple days if someone else maybe comes up with any idea, then i'll clean all things unbound related and i'll try again. and then i'll surrender. I did everything i could.. it's unfortunate because it's a couple weeks at least that i'm working on this raspbi, so i can't just clean it all and do it again.

Well can you at least tell me the way to have the absolute cleanest re-try of unbound config? what have i to delete and how?

And btw, thank you very very much to have taken the time to read and to help me. Really appreciated man.

1 Like

Unless you're using custom router firmware and settings the problem is related to read/write access of the root.key file. Unbound can't do DNSSEC unless it trusts the key file. Raspian Bullseye added a conf file to forward root processing to upstream DNS servers. Once Unbound can trust it's own root.key you can delete the forwarding code.

I would lower the logging verbosity to 2 then delete the log file and do a reboot to see the whole Unbound init process in the logs.
sudo rm /var/log/unbound/unbound.log
sudo touch /var/log/unbound/unbound.log
sudo chown unbound /var/log/unbound/unbound.log

If you don't see:
info: Successfully primed trust anchor . DNSKEY IN

Try to force and update of the root.key file:
sudo -u unbound unbound-anchor -v -F
In my setup the root.key file is owned by user & group unbound with 644 r/w access.

Actually i don't see it, but it says "resolving", and DNSKEY IN. isn't DNSKEY the .key file?

Nov 16 02:40:16 unbound[584:0] notice: init module 0: subnet
Nov 16 02:40:16 unbound[584:0] notice: init module 1: validator
Nov 16 02:40:16 unbound[584:0] notice: init module 2: iterator
Nov 16 02:40:16 unbound[584:0] info: start of service (unbound 1.13.1).
Nov 16 02:40:16 unbound[584:0] info: resolving . DNSKEY IN
Nov 16 02:40:16 unbound[584:0] info: priming . IN NS
Nov 16 02:40:16 unbound[584:0] info: error sending query to auth server 192.5.5.241 port 53

sudo -u unbound unbound-anchor -v -F :

/var/lib/unbound/root.key has content
debug cert update forced
/etc/unbound/icannbundle.pem: No such file or directory
using builtin certificate
have 1 trusted certificates
resolve data.iana.org A: no result
resolve data.iana.org AAAA: no result
data.iana.org has no IP addresses I can use

Edit: AH and now that i think of it Bucking_horn excluded the DNSSEC problem here:

Thanks to 'delv' command ( ? )

So my question for you are:
-Is the fact that i don't see

a problem or it's "DNSKEY IN" enough?

And more importantly: after what i quoted above do you still believe the problem is in the root key? i deleted it too to force unbound to make it anew but still SERVFAIL.

Yeah it's failing to prime the root trust. I would edit your /etc/dhcpcd.conf to point to 8.8.8.8 or whatever you want. Do a
sudo systemctl restart dhcpcd
to modity /etc/resolv.conf. Then kill the Unbound process.
sudo pkill -f unbound
sudo -u unbound unbound-anchor -v -F

It should be able to update the root.key now using the upstream DNS server

This is my results:
sudo -u unbound unbound-anchor -v -F
/var/lib/unbound/root.key has content
debug cert update forced
last successful probe: Tue Nov 15 18:21:50 2022
the last successful probe is recent
/etc/unbound/icannbundle.pem: No such file or directory
using builtin certificate
have 1 trusted certificates
resolved server address 152.199.24.38
resolved server address 2606:2800:21f:b505:516b:4186:98cd:116
connect to 2606:2800:21f:b505:516b:4186:98cd:116
fetched root-anchors/root-anchors.xml (690 bytes)
connect to 2606:2800:21f:b505:516b:4186:98cd:116
fetched root-anchors/root-anchors.p7s (2551 bytes)
signer 0: Subject: /O=ICANN/CN=DNSSEC Trust Anchor Verification/emailAddress=dnssec@iana.org
the PKCS7 signature verified
XML was parsed successfully, 1 keys
success: the anchor has been updated using the cert

If it's okay you can change /etc/resolv.conf back to 127.0.0.1 and do a reboot to load Unbound. If it still doesn't work then there is probably access permission/ownership issue of root.key.

1 Like

Well thanks you, here is 3:40 am so now i'm going to bed, i'll deal with that tomorrow.
By the way, in the meantime i manually wgetted both of .xml and the .p7s after a deep read of the unbound-anchor manual. Can't say i've well understood what i read, and let's just say it's time's fault, but still i got them. I hope it's not a permission problem, because i've chowned unbound:unbound almost anything except for the ' / '. if i go crazy tomorrow i might even try that.... good night

Excellent hint - thank you, bigpcjunky. :slight_smile:

It may be easier to point unbound-anchor at data.iana.org's IP address instead of editing dhcpcd.conf (which may not exist on any system, even more so since Raspberry Pi OS 11/Bullseye is preapring to move away from dhcpcd, giving you the the option to use NetworkManager instead):

dig data.iana.org +short @9.9.9.9

should return something similar to

ianadata.vip.icann.org.
152.199.24.38

Then use that IP for validating und updating the unbound-anchor, e.g.:

sudo -u unbound unbound-anchor -v -F -u 152.199.24.38

This didn't work, after all i had already configured my dhcpcd with static name as per my first post and never changed it. Same with resolvconf.conf, i had already manually changed it back to dhcpcd.conf ( dhcpcd restart didn't modify it anyway )

Did

dig data.iana.org +short @9.9.9.9

ianadata.vip.icann.org.

152.199.24.38

And then

sudo -u unbound unbound-anchor -v -F -u 152.199.24.38
/var/lib/unbound/root.key has content
debug cert update forced
have 1 trusted certificates
server address is 152.199.24.38
connect to 152.199.24.38
bad status 404 Not Found
could not fetch root-anchors/root-anchors.xml

Edit : ######Is it strange the line " ianadata.vip.icann.org." ?

To check my internet connection after 404 i did

nslookup data.iana.org
Server:		9.9.9.9
Address:	9.9.9.9#53

Non-authoritative answer:
data.iana.org	canonical name = ianadata.vip.icann.org.
Name:	ianadata.vip.icann.org
Address: 152.199.24.38
Name:	ianadata.vip.icann.org
Address: 2606:2800:21f:b505:516b:4186:98cd:116

so i know now why iandata isn't strange.
Still it doesn't work

No, nothing strange, just an ordinary CNAME.

Seems data.iana.org requires to be called by name.
I get a 404 as well when opening that xml via IP in my browser (EDIT: but can access it when using the name).

Since you seem to be using 9.9.9.9 for DNS anyway, try again without the IP:

sudo -u unbound unbound-anchor -v -F