Unbound stopped working properly after a power break

viktak · November 19, 2022, 2:07pm

The issue I am facing:
unbound is not resolving at all

Details about my system:
Raspberry Pi 2 Model B Rev 1.1
Raspbian GNU/Linux 11 (bullseye)

What I have changed since installing Pi-hole:
Nothing. It's been working for several months, and now we had a power break, and after that it stopped working.

Further details:
When I switch pihole to use another upstream DNS server, then dig dnssec.works @127.0.0.1 -p 5335 works correctly:

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

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

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

;; Query time: 90 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sat Nov 19 15:36:24 EET 2022
;; MSG SIZE  rcvd: 57

If I select 127.0.0.1#5335 as an upstream DNS server, the same command times out.

This is my config as reported by sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*

pi@pihole:~ $ 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/resolvconf_resolvers.conf:forward-zone:
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:  name: "local"
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:  forward-addr: 192.168.1.3
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:forward-zone:
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:  name: "."
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:  forward-addr: 192.168.1.3
/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
pi@pihole:~ $

unbound-checkconf doesn't report any issues:

pi@pihole:~ $ unbound-checkconf
unbound-checkconf: no errors in /etc/unbound/unbound.conf
pi@pihole:~ $

Finally, here are some logs:
Service start:

[1668866502] unbound[7939:0] debug: module config: "subnetcache validator iterator"
[1668866502] unbound[7939:0] notice: init module 0: subnet
[1668866502] unbound[7939:0] debug: subnet: option registered (8)
[1668866502] unbound[7939:0] notice: init module 1: validator
[1668866502] unbound[7939:0] notice: init module 2: iterator
[1668866502] unbound[7939:0] debug: target fetch policy for level 0 is 3
[1668866502] unbound[7939:0] debug: target fetch policy for level 1 is 2
[1668866502] unbound[7939:0] debug: target fetch policy for level 2 is 1
[1668866502] unbound[7939:0] debug: target fetch policy for level 3 is 0
[1668866502] unbound[7939:0] debug: target fetch policy for level 4 is 0
[1668866502] unbound[7939:0] debug: Forward zone server list:
[1668866502] unbound[7939:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
[1668866502] unbound[7939:0] debug: Forward zone server list:
[1668866502] unbound[7939:0] info: DelegationPoint<local.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
[1668866502] unbound[7939:0] debug: cache memory msg=33040 rrset=33040 infra=3920 val=33196 subnet=41372
[1668866502] unbound[7939:0] info: start of service (unbound 1.13.1).

Some (suspicious) entries:

[1668866665] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866665] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668866665] unbound[7939:0] info: iterator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: response for crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: reply from <.> 192.168.1.3#53
[1668866665] unbound[7939:0] info: query response was THROWAWAY
[1668866665] unbound[7939:0] info: processQueryTargets: crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: configured stub or forward servers failed -- returning SERVFAIL
[1668866665] unbound[7939:0] debug: return error response SERVFAIL
[1668866665] unbound[7939:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: validator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: subnet operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866665] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668866665] unbound[7939:0] info: iterator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: response for crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: reply from <.> 192.168.1.3#53
[1668866665] unbound[7939:0] info: query response was THROWAWAY
[1668866665] unbound[7939:0] info: processQueryTargets: crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: configured stub or forward servers failed -- returning SERVFAIL
[1668866665] unbound[7939:0] debug: return error response SERVFAIL
[1668866665] unbound[7939:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: validator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: subnet operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866665] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
[1668866665] unbound[7939:0] info: iterator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: response for crl.verisign.com. A IN
[1668866665] unbound[7939:0] info: reply from <.> 192.168.1.3#53
[1668866665] unbound[7939:0] info: query response was THROWAWAY
[1668866665] unbound[7939:0] info: processQueryTargets: crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: configured stub or forward servers failed -- returning SERVFAIL
[1668866665] unbound[7939:0] debug: return error response SERVFAIL
[1668866665] unbound[7939:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: validator operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1668866665] unbound[7939:0] info: subnet operate: query crl.verisign.com. A IN
[1668866665] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866666] unbound[7939:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
[1668866666] unbound[7939:0] info: subnet operate: query connectivitycheck.gstatic.com. A IN
[1668866666] unbound[7939:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1668866666] unbound[7939:0] info: validator operate: query connectivitycheck.gstatic.com. A IN
[1668866666] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
[1668866666] unbound[7939:0] info: resolving connectivitycheck.gstatic.com. A IN
[1668866666] unbound[7939:0] info: processQueryTargets: connectivitycheck.gstatic.com. A IN
[1668866666] unbound[7939:0] info: sending query: connectivitycheck.gstatic.com. A IN
[1668866666] unbound[7939:0] debug: sending to target: <.> 192.168.1.3#53
[1668866666] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866667] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
[1668866667] unbound[7939:0] info: iterator operate: query ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] info: processQueryTargets: ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] info: sending query: ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] debug: sending to target: <.> 192.168.1.3#53
[1668866667] unbound[7939:0] debug: cache memory msg=36793 rrset=37695 infra=4384 val=35263 subnet=41372
[1668866667] unbound[7939:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
[1668866667] unbound[7939:0] info: iterator operate: query ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] info: processQueryTargets: ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] info: sending query: ctldl.windowsupdate.com. A IN
[1668866667] unbound[7939:0] debug: sending to target: <.> 192.168.1.3#53

Could query response was THROWAWAY mean something?

Any idea what could cause this issue?

jpgpi250 · November 19, 2022, 2:35pm

throwaway means there is something wrong with the dnssec validation. Since you mentioned:

I would, as a first check verify your system time is correct, a key factor in dnssec validation.

viktak · November 19, 2022, 2:37pm

pi@pihole:~ $ timedatectl
               Local time: Sat 2022-11-19 16:36:02 EET
           Universal time: Sat 2022-11-19 14:36:02 UTC
                 RTC time: n/a
                Time zone: Europe/Athens (EET, +0200)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
pi@pihole:~ $

Since there is no RTC in the RPi, I'd assume, this is correct. right?

jpgpi250 · November 19, 2022, 2:45pm

dig +short +dnssec crl.verisign.com. should return something like:

crl-symcprod.digicert.com.
CNAME 8 3 60 20221218231841 20221118231841 864 verisign.com. kiJ6FzAIVFfLgXrSuNA80J4HuY1JyqOIVxq8NHURN5SCCSzXBalHJRQO 1NK8tn5IiQyAafXs47yuUENh705TkaURbymfizFaBfza4Pkz90BQq9DY h2MwJGIMBM2FwoowMxfKKhmzl9CnDMexqJP1ytUkhXdC1fHruuRxOxcX qN4=
cs9.wac.phicdn.net.
93.184.220.29

viktak · November 19, 2022, 2:53pm

For me it does not return anything, i.e.:

pi@pihole:~ $ dig +short +dnssec crl.verisign.com
pi@pihole:~ $

viktak · November 19, 2022, 2:57pm

I just noticed on my PiHole, on the Settings-DNS page, at the very bottom I can see this:

Although the fields are not editable, they are NOT correct. My network is 192.168.1.0/24 , and my DHCP server is 192.168.1.2. Could this be relevant? Where do I correct it?

jpgpi250 · November 19, 2022, 3:04pm

just noticed this in your unbound config. Did you read this? This basically creates a DNS loop, which makes the system behave unpredictable.

basically, it comes down to:

edit /etc/resolvconf.conf, make it look like this:

#dnsmasq_resolv=/var/run/dnsmasq/resolv.conf
pdnsd_conf=/etc/pdnsd.conf
#unbound_conf=/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf

comment out the unbound line (#).

delete the file /etc/unbound/unbound.conf.d/resolvconf_resolvers.conf
restart unbound

chrislph · November 19, 2022, 3:04pm

It's okay, that section is only used for Conditional Forwarding. Since you have it switched off those fields are not editable and are blank, showing examples of the notation needed should CF be switched on.

viktak · November 19, 2022, 3:56pm

Ah, ok, thanks for the explanantion!

viktak · November 19, 2022, 4:01pm

Yay, victory! Good catch!
This was the issue. Of course I haven't read that article... I just did, it makes sense..
Now, for the last few minutes it's been working flawlessly.
I wonder, though, what happened on the RPi. Is it possible that an update (as in apt update && apt upgrade) messed it up? Because it was really working just fine for many months..

Anyway, I'm glad it works again, I'm glad I learnt something new. And thank very much for your help!!!!!

jpgpi250 · November 19, 2022, 4:07pm

@yubiuser

might I suggest adding the dnsmasq setting dns-loop-detect

--dns-loop-detect
Enable code to detect DNS forwarding loops; ie the situation where a query sent to one of the upstream server eventually returns as a new query to the dnsmasq instance. The process works by generating TXT queries of the form <hex>.test and sending them to each upstream server. The hex is a UID which encodes the instance of dnsmasq sending the query and the upstream server to which it was sent. If the query returns to the server which sent it, then the upstream server through which it was sent is disabled and this event is logged. Each time the set of upstream servers changes, the test is re-run on all of them, including ones which were previously disabled.

Bucking_Horn · November 19, 2022, 4:33pm

We've indeed discussed this internally before and decided against it.

While dns-loop-detect sounds like a benefit on the surface, it actually adds less value then one would think. For once, it isn't a mere detection setting - if it concludes a DNS loop exists, dnsmasq will promptly remove the corresponding nameserver from its list of upstream resolvers. And it will stay disabled, unless the whole set of upstream servers would be changed (e.g. by adding another upstream DNS resolver via Pi-hole's UI).

On the other hand, a full DNS loop is something that you'd get aware of pretty quickly anyway, probably as quick or even quicker than with that option enabled.

But a partial DNS loop may only result in rather short, temporary spikes of DNS requests (e.g. as potentially closed by Conditional Fowarding in conjunction with a non-existing local hostname), not affecting resolution altogether.

Now, with dns-loop-detect active, dnsmasq would completely shun a corresponding upstream from being used altogether, disabling local hostname resolution completely - a bigger loss of functionality than without it.

EDIT:
What has changed since we'd had that discussion:
dnsmasq's warnings don't happen silently any more - they have since received a significant visibility boost via Pi-hole diagnosis.

system · December 10, 2022, 4:34pm

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.