Unbound doesn't work

That all looks normal. Check that you have content in both these files:

/var/lib/unbound/root.hints

/var/lib/unbound/root.key

And that the time on the Pi is correct for your locale.

If want to be absolutely sure, you could enable Unbound's remote-control by creating a config file with below:

sudo tee /etc/unbound/unbound.conf.d/remote-control.conf <<< $'remote-control:\n control-enable: yes'

And activate:

sudo service unbound reload

You can check if its recursing with below (something needs to be cached already):

pi@ph5b:~ $ sudo unbound-control lookup .
The following name servers are used for lookup of .
;rrset 86390 13 1 8 0
.       86390   IN      NS      e.root-servers.net.
.       86390   IN      NS      h.root-servers.net.
.       86390   IN      NS      l.root-servers.net.
.       86390   IN      NS      i.root-servers.net.
.       86390   IN      NS      a.root-servers.net.
.       86390   IN      NS      d.root-servers.net.
.       86390   IN      NS      c.root-servers.net.
.       86390   IN      NS      b.root-servers.net.
.       86390   IN      NS      j.root-servers.net.
.       86390   IN      NS      k.root-servers.net.
.       86390   IN      NS      g.root-servers.net.
.       86390   IN      NS      m.root-servers.net.
.       86390   IN      NS      f.root-servers.net.
[..]

And below would be wrong (10.0.0.1 being my router):

pi@ph5b:~ $ sudo unbound-control lookup .
The following name servers are used for lookup of .
forwarding request:
Delegation with 0 names, of which 0 can be examined to query further addresses.
It provides 1 IP addresses.
10.0.0.1                rto 315 msec, ttl 836, ping 3 var 78 rtt 315, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
1 Like

all looks fine. time is ok too

I did that but still shows nothing

root@raspberrypi:/home/pi> sudo unbound-control lookup .
The following name servers are used for lookup of .
no delegation from cache; goes to configured roots
root@raspberrypi:/home/pi>

First, you dont need above line!
If you read carefully:

pi@ph5a:~ $ cat /etc/unbound/unbound.conf.d/pi-hole.conf
[..]
    # Use this only when you downloaded the list of primary root servers!
    # If you use the default dns-root-data package, unbound will find it automatically
    #root-hints: "/var/lib/unbound/root.hints"

The dns-root-data package is automatically installed with unbound:

pi@ph5a:~ $ apt depends unbound
unbound
[..]
  Depends: dns-root-data
pi@ph5a:~ $ dpkg -L dns-root-data
[..]
/usr/share/dns/root.hints
pi@ph5a:~ $ head /usr/share/dns/root.hints
;       This file holds the information on root name servers needed to
;       initialize cache of Internet domain name servers
;       (e.g. reference this file in the "cache  .  <file>"
;       configuration file of BIND domain name servers).
;
;       This file is made available by InterNIC
;       under anonymous FTP as
;           file                /domain/named.cache
;           on server           FTP.INTERNIC.NET
;       -OR-                    RS.INTERNIC.NET

unbound will find it automatically like described in the remarks and it gets updated every time you run apt get upgrade.

Secondly, if above doesnt fix, you could up below verbosity for the logs if necessary and checkout the logs for errors/warnings:

pi@ph5a:~ $ man unbound.conf
[..]
       verbosity: <number>
              The  verbosity number, level 0 means no verbosity, only er‐
              rors. Level 1 gives operational information. Level 2  gives
              detailed operational information. Level 3 gives query level
              information, output per query.   Level  4  gives  algorithm
              level  information.  Level 5 logs client identification for
              cache misses.  Default is level 1.  The verbosity can  also
              be increased from the commandline, see unbound(8).

Probably in:

pi@ph5a:~ $ cat /etc/unbound/unbound.conf.d/pi-hole.conf
server:
    # If no logfile is specified, syslog is used
    # logfile: "/var/log/unbound/unbound.log"
    verbosity: 0

Or:

journalctl --full --no-pager -b -u unbound.service

Or follow/tail live:

journalctl --full --no-pager -f -u unbound.service

Ow blast, while solving an Unbound issue, I observed above is the exact response if dont consider below:

So the instructions should be:

sudo tee /etc/unbound/unbound.conf.d/remote-control.conf <<< $'remote-control:\n control-enable: yes'

unbound-checkconf

sudo service unbound reload

dig +noall @127.0.0.1 -p 5335 . ns

sudo unbound-control lookup .

EDIT: To disable remote-control again:

sudo rm /etc/unbound/unbound.conf.d/remote-control.conf

sudo service unbound reload

I removed root hints as you said. And, I did add remote control config and then did command below

sudo unbound-control lookup .
The following name servers are used for lookup of .
;rrset 44236 13 1 11 5
.	44236	IN	NS	g.root-servers.net.
.	44236	IN	NS	j.root-servers.net.
.	44236	IN	NS	e.root-servers.net.
.	44236	IN	NS	l.root-servers.net.
.	44236	IN	NS	d.root-servers.net.
.	44236	IN	NS	a.root-servers.net.
.	44236	IN	NS	b.root-servers.net.
.	44236	IN	NS	i.root-servers.net.
.	44236	IN	NS	m.root-servers.net.
.	44236	IN	NS	h.root-servers.net.
.	44236	IN	NS	c.root-servers.net.
.	44236	IN	NS	k.root-servers.net.
.	44236	IN	NS	f.root-servers.net.
.	44236	IN	RRSIG	NS 8 0 518400 20230309170000 20230224160000 951 . EGckAF/tzzcND0InCUcV3gVnaSSvOnptCgFfRJG4drpfVr/sRLs7WYrxJvlLxzKoXbakcRas7l40RmEivL2L6ZQbEPcKppdY79pdNoqSLPtgFuKL7qo+EgLLIJ72htgF9YKYAU41MJZsUfDXmp9dkMVC2NkY7x15lUq4WQTMvWSOR9Wz6GITrPXJQma6SsRqU00YV4upkZBb8+9palGZqIePBltHeKfGjCmQJ/2kRHxojO3HT5QMExSuNva2JFNXuyYFniAB8fpfM59Kp0688ItwS7FibcaG73BtDAg1fQGYTsMcIpAoJBJcnP+eSFp5EuKlL/yZQZK0N8+OK4OIaw== ;{id = 951}
;rrset 44236 1 0 3 0
f.root-servers.net.	44236	IN	A	192.5.5.241
;rrset 44236 1 0 3 0
f.root-servers.net.	44236	IN	AAAA	2001:500:2f::f
;rrset 44236 1 0 3 0
k.root-servers.net.	44236	IN	A	193.0.14.129
;rrset 44236 1 0 3 0
k.root-servers.net.	44236	IN	AAAA	2001:7fd::1
;rrset 44236 1 0 3 0
c.root-servers.net.	44236	IN	A	192.33.4.12
;rrset 44236 1 0 3 0
c.root-servers.net.	44236	IN	AAAA	2001:500:2::c
;rrset 44236 1 0 3 0
h.root-servers.net.	44236	IN	A	198.97.190.53
;rrset 44236 1 0 3 0
h.root-servers.net.	44236	IN	AAAA	2001:500:1::53
;rrset 44236 1 0 3 0
m.root-servers.net.	44236	IN	A	202.12.27.33
;rrset 44236 1 0 3 0
m.root-servers.net.	44236	IN	AAAA	2001:dc3::35
;rrset 44236 1 0 3 0
i.root-servers.net.	44236	IN	A	192.36.148.17
;rrset 44236 1 0 3 0
i.root-servers.net.	44236	IN	AAAA	2001:7fe::53
;rrset 44236 1 0 3 0
b.root-servers.net.	44236	IN	A	199.9.14.201
;rrset 44236 1 0 3 0
b.root-servers.net.	44236	IN	AAAA	2001:500:200::b
;rrset 44236 1 0 3 0
a.root-servers.net.	44236	IN	A	198.41.0.4
;rrset 44236 1 0 3 0
a.root-servers.net.	44236	IN	AAAA	2001:503:ba3e::2:30
;rrset 44236 1 0 3 0
d.root-servers.net.	44236	IN	A	199.7.91.13
;rrset 44236 1 0 3 0
d.root-servers.net.	44236	IN	AAAA	2001:500:2d::d
;rrset 44236 1 0 3 0
l.root-servers.net.	44236	IN	A	199.7.83.42
;rrset 44236 1 0 3 0
l.root-servers.net.	44236	IN	AAAA	2001:500:9f::42
;rrset 44236 1 0 3 0
e.root-servers.net.	44236	IN	A	192.203.230.10
;rrset 44236 1 0 3 0
e.root-servers.net.	44236	IN	AAAA	2001:500:a8::e
;rrset 44236 1 0 3 0
j.root-servers.net.	44236	IN	A	192.58.128.30
;rrset 44236 1 0 3 0
j.root-servers.net.	44236	IN	AAAA	2001:503:c27::2:30
;rrset 44236 1 0 3 0
g.root-servers.net.	44236	IN	A	192.112.36.4
;rrset 44236 1 0 3 0
g.root-servers.net.	44236	IN	AAAA	2001:500:12::d0d
Delegation with 13 names, of which 0 can be examined to query further addresses.
It provides 26 IP addresses.
2001:500:12::d0d	not in infra cache.
192.112.36.4    	NoAuthButRecursive rto 148 msec, ttl 724, ping 16 var 33 rtt 148, tA 0, tAAAA 0, tother 2, EDNS 0 probed.
2001:503:c27::2:30	not in infra cache.
192.58.128.30   	NoAuthButRecursive rto 504 msec, ttl 727, ping 4 var 62 rtt 252, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:500:a8::e  	not in infra cache.
192.203.230.10  	NoAuthButRecursive rto 196 msec, ttl 722, ping 16 var 45 rtt 196, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:500:9f::42 	not in infra cache.
199.7.83.42     	NoAuthButRecursive rto 137 msec, ttl 723, ping 5 var 33 rtt 137, tA 0, tAAAA 0, tother 2, EDNS 0 probed.
2001:500:2d::d  	not in infra cache.
199.7.91.13     	NoAuthButRecursive rto 594 msec, ttl 726, ping 1 var 74 rtt 297, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:503:ba3e::2:30	not in infra cache.
198.41.0.4      	NoAuthButRecursive rto 136 msec, ttl 722, ping 0 var 34 rtt 136, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:500:200::b 	not in infra cache.
199.9.14.201    	NoAuthButRecursive rto 274 msec, ttl 726, ping 1 var 34 rtt 137, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:7fe::53    	not in infra cache.
192.36.148.17   	NoAuthButRecursive rto 181 msec, ttl 726, ping 17 var 41 rtt 181, tA 0, tAAAA 0, tother 2, EDNS 0 probed.
2001:dc3::35    	not in infra cache.
202.12.27.33    	NoAuthButRecursive rto 145 msec, ttl 728, ping 17 var 32 rtt 145, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:500:1::53  	not in infra cache.
198.97.190.53   	NoAuthButRecursive rto 636 msec, ttl 722, ping 11 var 37 rtt 159, tA 0, tAAAA 0, tother 3, EDNS 0 probed.
2001:500:2::c   	not in infra cache.
192.33.4.12     	NoAuthButRecursive rto 968 msec, ttl 722, ping 76 var 223 rtt 968, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:7fd::1     	not in infra cache.
193.0.14.129    	NoAuthButRecursive rto 121 msec, ttl 725, ping 13 var 27 rtt 121, tA 0, tAAAA 0, tother 1, EDNS 0 probed.
2001:500:2f::f  	not in infra cache.
192.5.5.241     	NoAuthButRecursive rto 151 msec, ttl 724, ping 3 var 37 rtt 151, tA 0, tAAAA 0, tother 0, EDNS 0 probed.

However, sometimes lookup for . returns nothing. I didn't figure out why.

sudo unbound-control lookup .
The following name servers are used for lookup of .
no delegation from cache; goes to configured roots

and still looking up domains don't work (or sometimes returns wrong IP)

dig +noall @127.0.0.1 -p 5335 google.com
;; connection timed out; no servers could be reached

dig @127.0.0.1 -p 5335 google.com

; <<>> DiG 9.11.5-P4-5.1+deb10u8-Raspbian <<>> @127.0.0.1 -p 5335 google.com
; (1 server found)
;; global options: +cmd
;; connection timed out; no servers could be reached

and this is my verbos log


Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. A IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: validator: nextmodule returned
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_INIT_STATE
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: validator classification positive
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: no signer, using google.com. TYPE0 CLASS0
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: validator: FindKey google.com. A IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: current keyname com. DNSKEY IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: target keyname google.com. DNSKEY IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: striplab 0
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: next keyname google.com. DNSKEY IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: No DS RRset
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: generate request google.com. DS IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_wait_subquery
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. DS IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: subnet: pass to next module
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_wait_module
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. DS IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: validator: pass to next module
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_wait_module
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: process_request: new external request event
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state INIT REQUEST STATE
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: resolving google.com. DS IN
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: request has dependency depth of 0
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
                                           ;; flags: qr ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 6, ADDITIONAL: 0
                                           ;; QUESTION SECTION:
                                           google.com.        IN        DS

                                           ;; ANSWER SECTION:

                                           ;; AUTHORITY SECTION:
                                           CK0POJMG874LJREF7EFN8430QVIT8BSM.com.        20857        IN        NSEC3        1 1 0 - ck0q2d6ni4i7eqh8na30ns61o48ul8g5 NS SOA RRSIG DNSKEY NSEC3PARAM ;{flags: optout}
                                           CK0POJMG874LJREF7EFN8430QVIT8BSM.com.        20857        IN        RRSIG        NSEC3 8 2 86400 20230303052249 20230224041249 36739 com. rXXhjgHhBHyFnZNsXtNvn2jSCLCInjirm5afZvn+wcu2dIQ/wGP9TAbtZXDgA78A21Bgbtfm04wVemAUSg3dOBWZaPGJqftBUffy9mr8eSFeOfe4cx35PzknJp6BVqUwYGQtogdUu9A7iFldK6AJhFWpeIL194qhtJY6kQMdHRmL3S8kgI5KbxzpzB90bWpetBPxs493GpP/R4pBvH2nsA== ;{id = 36739}
                                           com.        3548        IN        SOA        a.gtld-servers.net. nstld.verisign-grs.com. 1677306908 1800 900 604800 86400
                                           com.        20857        IN        RRSIG        SOA 8 1 900 20230304063508 20230225052508 36739 com. tlRS6ij1Co1cm98lbP7Vu5FrQyE10lbTwo6y2lTBM71DAbraUx+hK7zdR9YC5PzedqKXbkVdZA0UJHVjCH1M3NGahSVuCKHyipM05/5MwjGfNxOqQ6P87DmaIkC0pt8TgWBQue9+gRk6iiFuraKnPUj79mTTet6u+u+QsZOOvCNbjV5W0tXX6CWdXQrt3UFonNLmbSJaC4cIP5Rez0K5Eg== ;{id = 36739}
                                           S84BKCIBC38P58340AKVNFN5KR9O59QC.com.        20857        IN        NSEC3        1 1 0 - s84buo64gqcvn69rjfuo6lvc7fslunj5 NS DS RRSIG ;{flags: optout}
                                           S84BKCIBC38P58340AKVNFN5KR9O59QC.com.        20857        IN        RRSIG        NSEC3 8 2 86400 20230304060135 20230225045135 36739 com. cXaYy0la+1W3vD6vMRJqyuTMycvYhTRWUBA2ytY9LPwTzcN6wP1WUp9D9ZtFK5A4aTavzz28nFy53WLCDsWYWr3ogIb5M0BGjZqFZ3oHIwmqgRwhgG+8P/etYTW1TTfDQQXo0mGGc50D1GLzhTMiBnKJsTir3xLcbq8Mx1y0Cp/DlRQkV+RC4o8USaWA4E3Ib0gbG36KMa2DBIYswFgpxA== ;{id = 36739}

                                           ;; ADDITIONAL SECTION:
                                           ;; MSG SIZE  rcvd: 845
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: msg ttl is 3548, prefetch ttl 3188
Feb 25 07:04:38 raspberrypi unbound[9636]: [9636:0] debug: returning answer from cache.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: finishing processing for google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator: nextmodule returned
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: not validating response, is valrec(validation recursion lookup)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator: inform_super, sub is google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: super is google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: nsec3: keysize 1280 bits, max iterations 500
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: ce candidate com. TYPE0 CLASS0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: NSEC3s for the referral proved no DS.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: Verified that unsigned response is INSECURE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_FINISHED_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: query took 22.472322 sec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 7 recursion replies sent, 0 replies dropped, 0 states jostled out
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: average recursion processing time 18.317582 sec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: histogram of recursion processing times
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: [25%]=7 median[50%]=20.8 [75%]=26.4
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: lower(secs) upper(secs) recursions
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    2.000000    4.000000 1
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    4.000000    8.000000 1
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   16.000000   32.000000 5
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: 0RDd mod2 rep google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: cache memory msg=37167 rrset=41815 infra=16157 val=36012 subnet=41372
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks end
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: close of port 53976
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: close fd 12
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: answer cb
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply id = a983
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply addr = ip4 198.18.1.138 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: lookup size is 1 entries
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: received udp reply.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: udp message[55:0] A9838490000100010000000106676F6F676C6503636F6D0000010001C00C00010001000000010004C612001000002904D0000000010000
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: outnet handle udp reply
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: measured roundtrip at 2012 msec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks start
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: worker svcd callback for qstate 0x1732ec8
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: iterator operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: process_response: new external response event
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: scrub for com. NS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: response for google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: reply from <com.> 198.18.1.138#53
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
                                           ;; flags: qr aa ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
                                           ;; QUESTION SECTION:
                                           google.com.        IN        A

                                           ;; ANSWER SECTION:
                                           google.com.        1        IN        A        198.18.0.16

                                           ;; AUTHORITY SECTION:

                                           ;; ADDITIONAL SECTION:
                                           ;; MSG SIZE  rcvd: 44
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: query response was DNSSEC LAME
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: processQueryTargets: google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 3
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: DelegationPoint<com.>: 13 names (7 missing), 6 addrs (4 result, 2 avail) cacheNS
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   j.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   h.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   e.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   f.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   d.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   i.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   m.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   a.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   b.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   l.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   g.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   k.gtld-servers.net. * A
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   c.gtld-servers.net.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.135 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.146 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.147 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.134 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.138 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    ip4 198.18.1.143 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.146 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=3497
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.135 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=11836
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.138 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=5554
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.147 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=5797
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.134 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=7822
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 198.18.1.143 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug:    rtt=7436
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: selrtt 3497
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: sending query: google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: sending to target: <com.> 198.18.1.146#53
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: dnssec status: expected
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: EDNS lookup known=1 vs=0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: serviced query UDP timeout=3497 msec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: inserted new pending reply id=c7ef
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: opened UDP if=0 port=31056
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: comm point start listening 12
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_wait_reply
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 7 recursion replies sent, 0 replies dropped, 0 states jostled out
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: average recursion processing time 18.317582 sec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: histogram of recursion processing times
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: [25%]=7 median[50%]=20.8 [75%]=26.4
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: lower(secs) upper(secs) recursions
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    2.000000    4.000000 1
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    4.000000    8.000000 1
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:   16.000000   32.000000 5
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: 0RDd mod2 rep google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: cache memory msg=37167 rrset=41815 infra=16157 val=36012 subnet=41372
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks end
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: close of port 30113
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: close fd 13
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: answer cb
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply id = c7ef
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply addr = ip4 198.18.1.146 port 53 (len 16)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: lookup size is 1 entries
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: received udp reply.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: udp message[55:0] C7EF8490000100010000000106676F6F676C6503636F6D0000010001C00C00010001000000010004C612001000002904D0000000010000
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: outnet handle udp reply
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: measured roundtrip at 36 msec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks start
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: worker svcd callback for qstate 0x1732ec8
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: iterator operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: process_response: new external response event
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: scrub for com. NS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: response for google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: reply from <com.> 198.18.1.146#53
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
                                           ;; flags: qr aa ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
                                           ;; QUESTION SECTION:
                                           google.com.        IN        A

                                           ;; ANSWER SECTION:
                                           google.com.        1        IN        A        198.18.0.16

                                           ;; AUTHORITY SECTION:

                                           ;; ADDITIONAL SECTION:
                                           ;; MSG SIZE  rcvd: 44
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: query response was ANSWER
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: finishing processing for google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator: nextmodule returned
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_INIT_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator classification positive
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: no signer, using google.com. TYPE0 CLASS0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator: FindKey google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: current keyname com. DNSKEY IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: target keyname google.com. DNSKEY IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: striplab 0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: next keyname google.com. DNSKEY IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: No DS RRset
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: generate request google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_wait_subquery
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet: pass to next module
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_wait_module
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator: pass to next module
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_wait_module
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: process_request: new external request event
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state INIT REQUEST STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: resolving google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: request has dependency depth of 0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
                                           ;; flags: qr ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 6, ADDITIONAL: 0
                                           ;; QUESTION SECTION:
                                           google.com.        IN        DS

                                           ;; ANSWER SECTION:

                                           ;; AUTHORITY SECTION:
                                           CK0POJMG874LJREF7EFN8430QVIT8BSM.com.        20856        IN        NSEC3        1 1 0 - ck0q2d6ni4i7eqh8na30ns61o48ul8g5 NS SOA RRSIG DNSKEY NSEC3PARAM ;{flags: optout}
                                           CK0POJMG874LJREF7EFN8430QVIT8BSM.com.        20856        IN        RRSIG        NSEC3 8 2 86400 20230303052249 20230224041249 36739 com. rXXhjgHhBHyFnZNsXtNvn2jSCLCInjirm5afZvn+wcu2dIQ/wGP9TAbtZXDgA78A21Bgbtfm04wVemAUSg3dOBWZaPGJqftBUffy9mr8eSFeOfe4cx35PzknJp6BVqUwYGQtogdUu9A7iFldK6AJhFWpeIL194qhtJY6kQMdHRmL3S8kgI5KbxzpzB90bWpetBPxs493GpP/R4pBvH2nsA== ;{id = 36739}
                                           com.        3547        IN        SOA        a.gtld-servers.net. nstld.verisign-grs.com. 1677306908 1800 900 604800 86400
                                           com.        20856        IN        RRSIG        SOA 8 1 900 20230304063508 20230225052508 36739 com. tlRS6ij1Co1cm98lbP7Vu5FrQyE10lbTwo6y2lTBM71DAbraUx+hK7zdR9YC5PzedqKXbkVdZA0UJHVjCH1M3NGahSVuCKHyipM05/5MwjGfNxOqQ6P87DmaIkC0pt8TgWBQue9+gRk6iiFuraKnPUj79mTTet6u+u+QsZOOvCNbjV5W0tXX6CWdXQrt3UFonNLmbSJaC4cIP5Rez0K5Eg== ;{id = 36739}
                                           S84BKCIBC38P58340AKVNFN5KR9O59QC.com.        20856        IN        NSEC3        1 1 0 - s84buo64gqcvn69rjfuo6lvc7fslunj5 NS DS RRSIG ;{flags: optout}
                                           S84BKCIBC38P58340AKVNFN5KR9O59QC.com.        20856        IN        RRSIG        NSEC3 8 2 86400 20230304060135 20230225045135 36739 com. cXaYy0la+1W3vD6vMRJqyuTMycvYhTRWUBA2ytY9LPwTzcN6wP1WUp9D9ZtFK5A4aTavzz28nFy53WLCDsWYWr3ogIb5M0BGjZqFZ3oHIwmqgRwhgG+8P/etYTW1TTfDQQXo0mGGc50D1GLzhTMiBnKJsTir3xLcbq8Mx1y0Cp/DlRQkV+RC4o8USaWA4E3Ib0gbG36KMa2DBIYswFgpxA== ;{id = 36739}

                                           ;; ADDITIONAL SECTION:
                                           ;; MSG SIZE  rcvd: 845
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: msg ttl is 3547, prefetch ttl 3187
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: returning answer from cache.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: finishing processing for google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator: nextmodule returned
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: not validating response, is valrec(validation recursion lookup)
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator: inform_super, sub is google.com. DS IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: super is google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: nsec3: keysize 1280 bits, max iterations 500
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: ce candidate com. TYPE0 CLASS0
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: NSEC3s for the referral proved no DS.
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: validator operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: Verified that unsigned response is INSECURE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_FINISHED_STATE
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query google.com. A IN
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_finished
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] debug: query took 20.385447 sec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 8 recursion replies sent, 0 replies dropped, 0 states jostled out
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: average recursion processing time 18.576065 sec
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: histogram of recursion processing times
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: [25%]=8 median[50%]=21.3333 [75%]=26.6667
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info: lower(secs) upper(secs) recursions
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    2.000000    4.000000 1
Feb 25 07:04:39 raspberrypi unbound[9636]: [9636:0] info:    4.000000    8.000000 1
Feb 25 07:04:40 raspberrypi unbound[9636]: [9636:0] info:   16.000000   32.000000 6
Feb 25 07:04:40 raspberrypi unbound[9636]: [9636:0] debug: cache memory msg=37167 rrset=41815 infra=16157 val=36012 subnet=41372
Feb 25 07:04:40 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks end
Feb 25 07:04:40 raspberrypi unbound[9636]: [9636:0] debug: close of port 31056
Feb 25 07:04:40 raspberrypi unbound[9636]: [9636:0] debug: close fd 12

in order to figure out the issue I changed Clash mode to redir-host so no more fake-ip

I ran dig and I can see in logs the correct IP (or maybe I'm wrong) but it returns with SERVFAIL

Feb 25 11:31:38 raspberrypi unbound[9636]: [9636:0] debug: new control connection from ip4 127.0.0.1 port 36694 (len 16)
Feb 25 11:31:38 raspberrypi unbound[9636]: [9636:0] debug: comm point stop listening 12
Feb 25 11:31:38 raspberrypi unbound[9636]: [9636:0] debug: comm point start listening 12
Feb 25 11:31:39 raspberrypi unbound[9636]: [9636:0] debug: remote control connection authenticated
Feb 25 11:31:39 raspberrypi unbound[9636]: [9636:0] info: control cmd:  lookup .
Feb 25 11:31:39 raspberrypi unbound[9636]: [9636:0] debug: remote control operation completed
Feb 25 11:31:39 raspberrypi unbound[9636]: [9636:0] debug: close fd 12
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: subnet: pass to next module
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_wait_module
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: validator operate: query dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: validator: pass to next module
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_wait_module
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: process_request: new external request event
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state INIT REQUEST STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: resolving dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: request has dependency depth of 0
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: cache blacklisted, going to the network
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: cache delegation returns delegpt
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: DelegationPoint<dnssec.works.>: 2 names (2 missing), 2 addrs (0 result, 2 avail) cacheNS
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   ns5.myinfrastructure.org.  A
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   ns3.myinfrastructure.org.  A
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    ip4 5.45.109.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    ip4 185.92.221.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: resolving (init part 2):  dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: resolving (init part 3):  dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: processQueryTargets: dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: DelegationPoint<dnssec.works.>: 2 names (0 missing), 2 addrs (0 result, 2 avail) cacheNS
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   ns5.myinfrastructure.org. * A
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   ns3.myinfrastructure.org. * A
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    ip4 5.45.109.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    ip4 185.92.221.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: attempt to get extra 3 targets
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 185.92.221.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    rtt=2291 DNSSEC_LAME
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: servselect ip4 5.45.109.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug:    rtt=2575 DNSSEC_LAME
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: selrtt 242291
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: chase to dnssec lame server
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: sending query: dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: sending to target: <dnssec.works.> 185.92.221.212#53
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: dnssec status: expected but lame_query anyway
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: EDNS lookup known=1 vs=0
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: serviced query UDP timeout=2291 msec
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: inserted new pending reply id=9f93
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: opened UDP if=0 port=6285
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: comm point start listening 12
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_wait_reply
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: mesh_run: end 1 recursion states (0 with reply, 1 detached), 0 waiting replies, 27 recursion replies sent, 0 replies dropped, 0 states jostled out
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: average recursion processing time 63.316339 sec
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: histogram of recursion processing times
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: [25%]=10 median[50%]=24 [75%]=72
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: lower(secs) upper(secs) recursions
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    0.065536    0.131072 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    0.524288    1.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    1.000000    2.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    2.000000    4.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    4.000000    8.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    8.000000   16.000000 3
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   16.000000   32.000000 9
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   32.000000   64.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   64.000000  128.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:  128.000000  256.000000 3
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:  256.000000  512.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: 0RDd mod2  dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: answer cb
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply id = 9f93
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: Incoming reply addr = ip4 185.92.221.212 port 53 (len 16)
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: lookup size is 1 entries
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: received udp reply.
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: udp message[293:0] 9F938490000100020000000106646E7373656305776F726B730000010001C00C0001000100000A390004052D6B58C00C002E000100000A3900E00001080200000E106412AFC963EB1FC5F74A06646E7373656305776F726B730037F6EC3C3DE862D075E94856F86020218CC3B5AF9F238BAD14C4D9B1032D4DBA0C907F26C2A7EF2294AD136E0393E6F04CD854A76988F589D8565B5BA94E0B5E4079AA31A031D354BAE0D30CDED24A8AC486849619001D1496B6759743365E256C18AA714697F7ABF920564860EE749F3FEAA03A67F147DC1575AD10C064DB0B13C63AA107E79D8BB87042F0E29E8048BFE7AD723B5F6AF9076BA316D414AF2EABE314136A4A
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: udp message[293:256] 150DD5D51095227FA36EB6670B4B1A8454A9AC2F58293949E12A000029020000000A390000
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: outnet handle udp reply
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: measured roundtrip at 40 msec
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks start
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: worker svcd callback for qstate 0x171eea0
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: iterator operate: query dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: process_response: new external response event
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: scrub for dnssec.works. NS IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: response for dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: reply from <dnssec.works.> 185.92.221.212#53
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
                                           ;; flags: qr aa ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
                                           ;; QUESTION SECTION:
                                           dnssec.works.        IN        A

                                           ;; ANSWER SECTION:
                                           dnssec.works.        2617        IN        A        5.45.107.88
                                           dnssec.works.        2617        IN        RRSIG        A 8 2 3600 20230316055729 20230214054437 63306 dnssec.works. N/bsPD3oYtB16UhW+GAgIYzDta+fI4utFMTZsQMtTboMkH8mwqfvIpStE24Dk+bwTNhUp2mI9YnYVltbqU4LXkB5qjGgMdNUuuDTDN7SSorEhoSWGQAdFJa2dZdDNl4lbBiqcUaX96v5IFZIYO50nz/qoDpn8UfcFXWtEMBk2wsTxjqhB+edi7hwQvDinoBIv+etcjtfavkHa6MW1BSvLqvjFBNqShUN1dUQlSJ/o262ZwtLGoRUqawvWCk5SeEq ;{id = 63306}

                                           ;; AUTHORITY SECTION:

                                           ;; ADDITIONAL SECTION:
                                           ;; MSG SIZE  rcvd: 282
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: query response was ANSWER
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: finishing processing for dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: iterator module exit state is module_finished
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: validator operate: query dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: validator: nextmodule returned
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_INIT_STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: validator classification positive
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: signer is dnssec.works. TYPE0 CLASS0
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: val handle processing q with state VAL_FINISHED_STATE
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: validator module exit state is module_finished
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: subnet operate: query dnssec.works. A IN
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: subnet module exit state is module_finished
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 27 recursion replies sent, 0 replies dropped, 0 states jostled out
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: average recursion processing time 63.316339 sec
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: histogram of recursion processing times
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: [25%]=10 median[50%]=24 [75%]=72
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info: lower(secs) upper(secs) recursions
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    0.065536    0.131072 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    0.524288    1.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    1.000000    2.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    2.000000    4.000000 1
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    4.000000    8.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:    8.000000   16.000000 3
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   16.000000   32.000000 9
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   32.000000   64.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:   64.000000  128.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:  128.000000  256.000000 3
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] info:  256.000000  512.000000 2
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: cache memory msg=42701 rrset=51992 infra=18961 val=38596 subnet=41372
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: svcd callbacks end
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: close of port 6285
Feb 25 11:32:01 raspberrypi unbound[9636]: [9636:0] debug: close fd 12

commands I ran

dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.11.5-P4-5.1+deb10u8-Raspbian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 60905
;; 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: 13 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Sat Feb 25 11:32:01 GMT 2023
;; MSG SIZE  rcvd: 41

dig dnssec.works @127.0.0.1 -p 5335

; <<>> DiG 9.11.5-P4-5.1+deb10u8-Raspbian <<>> dnssec.works @127.0.0.1 -p 5335
;; global options: +cmd
;; connection timed out; no servers could be reached

btw, this is what I see on Pihole log. what does "INSECURE" means?

Thats odd.
Those "." and "XXX.root-servers.net" records should stay cached by unbound for at least 44236 seconds (approximately 12 hours):

If you get that "no delegation from cache" message intermittently within those 12 hours, it sounds as if unbound gets restarted or some other process that clears cache.

Does your Pi-hole host have an IPv6 GUA address?

ip -br -6 a

Dont post your full global address here for privacy but partially redact it eg 2001:XXXX !!!

If the host got an IPv6 global address via IPv6 SLAAC/NDRA, the router might periodicly change the prefix (coming from your ISP) via IPv6 router advertisement(RA).
Whenever the advertised prefix changes, the IP changes.
And when the IP changes, unbound gets restarted.
A rudimentary way of purging the old IPv6 details that were in cache.
I dont have IPv6 at home but thats what I could make up from below:

Do you see unbound getting restarted frequently with below?

journalctl --full --no-pager -b -u unbound

See below:

https://docs.pi-hole.net/ftldns/dnsmasq_warn/?h=insecure

You can also check for GUA with:

dig -t aaaa +short myip.opendns.com @resolver1.opendns.com

or

curl https://api64.ipify.org

1 Like

Does curl ifconfig.me show the GUA?
Or is it IPv4 only?

I don't know, I don't have anything set up with GUA addressing that I can access easily.

curl -6 https://ifconfig.me would tell you if you can even access the IPv6 public space, but api64.ipify.org does the same and I trust https://ipify.org more than any of the other options available.

1 Like

yes it does fd8c:XXXX:XXXX::141/128 fd8c:XXXX:XXXX:0:XXXX:8eda:e39c:e32f/64 fe80::XXXX:XXXX:429f:3aae/64

I will check this again to see if it's changing.

it looks like it

pi@raspberrypi:~ $ journalctl --full --no-pager -b -u unbound | grep start
Feb 27 19:11:26 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:31 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:35 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:39 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:42 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:46 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start
Feb 27 19:11:49 raspberrypi unbound[9636]: [9636:0] debug: mesh_run: start

this returns nothing.

curl https://api64.ipify.org
45.XXX.XXX.116

this is IPv4. when I start OpenClash, it returns a IPv6

Could you provide below info pls?

cat /proc/device-tree/model; echo

lsb_release -d

apt policy unbound

unbound -h | grep Version

Above are not GUA addresses.
The fe80 one is a LLA.
And both fd8c ones are ULA's.

Do you notice any of them changing frequently?
EDIT: Below might hint but am not sure as I dont have IPv6 on my LAN:

journalctl --full --no-pager -b -u dhcpcd.service

I must say that I'm not that well versed with interpreting the unbound logs but above doesnt look like a restart:

pi@ph5b:~ $ journalctl --full --no-pager -b -u unbound | grep start
Jan 04 04:54:33 ph5b unbound[322]: [322:0] info: start of service (unbound 1.13.1).
Feb 12 20:42:31 ph5b unbound[6613]: [6613:0] info: start of service (unbound 1.13.1).
Feb 12 20:45:11 ph5b unbound[6678]: [6678:0] info: start of service (unbound 1.13.1).
Feb 19 01:02:49 ph5b unbound[16581]: [16581:0] info: start of service (unbound 1.13.1).
Feb 24 07:15:49 ph5b unbound[16581]: [16581:0] info: start of service (unbound 1.13.1).

Plus I would try and grep for below instead:

pi@ph5b:~ $ journalctl --full --no-pager -b -u unbound | grep -i 'start\|stop'
Jan 04 04:54:20 ph5b systemd[1]: Starting Unbound DNS server...
Jan 04 04:54:33 ph5b systemd[1]: Started Unbound DNS server.
Jan 04 04:54:33 ph5b unbound[322]: [322:0] info: start of service (unbound 1.13.1).
Feb 12 20:42:29 ph5b unbound[322]: [322:0] info: service stopped (unbound 1.13.1).
Feb 12 20:42:29 ph5b systemd[1]: Stopping Unbound DNS server...
Feb 12 20:42:30 ph5b systemd[1]: Stopped Unbound DNS server.
[..]

Your distro major version release doesnt support it probably but you can also grep with journalctl and the -g argument eg:

pi@ph5b:~ $ journalctl --full --no-pager -b -u unbound -g 'start|stop'
-- Journal begins at Thu 2021-06-24 03:50:00 CEST, ends at Wed 2023-03-01 12:50:01 CET. --
Jan 04 04:54:20 ph5b systemd[1]: Starting Unbound DNS server...
Jan 04 04:54:33 ph5b systemd[1]: Started Unbound DNS server.
Jan 04 04:54:33 ph5b unbound[322]: [322:0] info: start of service (unbound 1.13.1).
Feb 12 20:42:29 ph5b unbound[322]: [322:0] info: service stopped (unbound 1.13.1).
Feb 12 20:42:29 ph5b systemd[1]: Stopping Unbound DNS server...
Feb 12 20:42:30 ph5b systemd[1]: Stopped Unbound DNS server.
[..]

I have no idea what to look for to be honest.
I would suggest to keep two ssh sessions open (or in screen if familiar with that).

Below one that runs every minute (60 seconds) to spot those "no delegation from cache" messages when they occur:

sudo watch -n 60 unbound-control lookup .

As said before, they should stay cached for at least 12 hours.
And maybe you have to adjust the 60 seconds interval to better suit your circumstances.

And below one to tail/follow the journals live to see what new entries are logged when this happens:

journalctl --full --no-pager -f -u unbound.service

At the same time, I would advice not to configure unbound to be used as upstream for Pi-hole.
This so the logs dont get swamped with queries from your clients.

EDIT: Ow below might come in handy.
If you run this one a couple of times, you can see the TTL for the cached records counting down:

dig +noall +answer @localhost -p 5335 . ns

Similar as with unbound-control lookup . but less verbose.

I think I maybe found a hint in below:

Above looks akward and should resemble below or similar to my knowledge for unbound v1.9:

pi@ph5a:~ $ sudo unbound-control lookup .
The following name servers are used for lookup of .
[..]
Delegation with 13 names, of which 0 can be examined to query further addresses.
It provides 26 IP addresses.
2001:503:ba3e::2:30     not in infra cache.
198.41.0.4              expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:200::b         not in infra cache.
199.9.14.201            expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:2::c           not in infra cache.
192.33.4.12             expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:2d::d          not in infra cache.
199.7.91.13             expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:a8::e          not in infra cache.
192.203.230.10          expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:2f::f          not in infra cache.
192.5.5.241             expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:12::d0d        not in infra cache.
192.112.36.4            expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:1::53          not in infra cache.
198.97.190.53           expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:7fe::53            not in infra cache.
192.36.148.17           expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:503:c27::2:30      not in infra cache.
192.58.128.30           expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:7fd::1             not in infra cache.
193.0.14.129            expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:500:9f::42         not in infra cache.
199.7.83.42             expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.
2001:dc3::35            not in infra cache.
202.12.27.33            expired, rto 187184 msec, tA 0 tAAAA 0 tother 0.

And the NoAuthButRecursive bit looked familiar to me:

Checkout solution for that one.
There might be some DNS filtering/redirecting going on upstream that bugs the system.

2 Likes

The issue I have is ISP-level DNS hijacking, like the topic you mentioned. Sadly, I cannot turn it off.

Iran is using both DNS hijacking and DPI to block internet access to many services. I though Unbound could fix that issue for me. Apparently not.

1 Like

Well if they sniff properly, there is no way to fix this with DNS only.
Everything SSL/TLS related will get sniffed for the unencrypted SNI thats communicated:

So even if you get the DNS right, they are still able to block/filter:

pi@ph5b:~ $ curl -I https://pi-hole.net
HTTP/1.1 200 OK
[..]
pi@ph5b:~ $ sudo tcpdump -nqtX tcp port 443
[..]
IP 10.0.0.4.49146 > 3.18.136.52.443: tcp 517
[..]
        0x00c0:  0100 0175 0000 0010 000e 0000 0b70 692d  ...u.........pi-
        0x00d0:  686f 6c65 2e6e 6574 000b 0004 0300 0102  hole.net........

Sounds like you have to go the VPN way to get through.

No indeed, and it doesn't make any promises matching that purpose.
unbound is querying the authoritative DNS servers instead of your ISP's or some other public DNS resolvers. That may add to your privacy, as no public DNS resolver would have your DNS history to analyse - but if DNS traffic is forcefully redirected, that would not work, obviously.

is there any way of getting around DNS poisoning? if Unbound isn't the solution, what is?

want to have pihole locally for speed reasons

Difficult.
Traditional Do53 (DNS over port 53) is easy to block bc it doesnt have encryption.
DoT can be blocked by blocking the DoT servers like that of Cloudflare:

And even DoH depends on TLS for which we know they can sniff the SNI:

And known VPN providers can be blocked also.

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