Pi-hole + unbound default setup not working on validation

aamm19 · January 9, 2023, 12:32am

Hello internet,

First off, happy holidays to everyone. After end of year shenanigans, I picked up this project again and with the current setup I'm using I configured my computer as the only client for Pi-hole, and I'm seeing some results in the logs:

Jan 08 18:28:11 unbound[1445:0] debug: answer from the cache failed
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: start
Jan 08 18:28:11 unbound[1445:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Jan 08 18:28:11 unbound[1445:0] info: subnet operate: query searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: subnet: not found in cache. pass to next module
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: subnet module exit state is module_wait_module
Jan 08 18:28:11 unbound[1445:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Jan 08 18:28:11 unbound[1445:0] info: validator operate: query searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: validator: pass to next module
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: validator module exit state is module_wait_module
Jan 08 18:28:11 unbound[1445:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Jan 08 18:28:11 unbound[1445:0] debug: process_request: new external request event
Jan 08 18:28:11 unbound[1445:0] debug: iter_handle processing q with state INIT REQUEST STATE
Jan 08 18:28:11 unbound[1445:0] info: resolving searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: request has dependency depth of 0
Jan 08 18:28:11 unbound[1445:0] debug: forwarding request
Jan 08 18:28:11 unbound[1445:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Jan 08 18:28:11 unbound[1445:0] info: processQueryTargets: searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Jan 08 18:28:11 unbound[1445:0] info: DelegationPoint<.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
Jan 08 18:28:11 unbound[1445:0] debug:    ip6 fe80::1 port 53 (len 28)
Jan 08 18:28:11 unbound[1445:0] debug: attempt to get extra 3 targets
Jan 08 18:28:11 unbound[1445:0] debug: No more query targets, attempting last resort
Jan 08 18:28:11 unbound[1445:0] debug: configured stub or forward servers failed -- returning SERVFAIL
Jan 08 18:28:11 unbound[1445:0] debug: store error response in message cache
Jan 08 18:28:11 unbound[1445:0] debug: return error response SERVFAIL
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: iterator module exit state is module_finished
Jan 08 18:28:11 unbound[1445:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Jan 08 18:28:11 unbound[1445:0] info: validator operate: query searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: validator: nextmodule returned
Jan 08 18:28:11 unbound[1445:0] debug: cannot validate non-answer, rcode SERVFAIL
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: validator module exit state is module_finished
Jan 08 18:28:11 unbound[1445:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Jan 08 18:28:11 unbound[1445:0] info: subnet operate: query searx.net. A IN
Jan 08 18:28:11 unbound[1445:0] debug: mesh_run: subnet module exit state is module_finished
Jan 08 18:28:11 unbound[1445:0] debug: query took 0.000000 sec
Jan 08 18:28:11 unbound[1445:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 86 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 08 18:28:11 unbound[1445:0] info: average recursion processing time 0.000000 sec
Jan 08 18:28:11 unbound[1445:0] info: histogram of recursion processing times
Jan 08 18:28:11 unbound[1445:0] info: [25%]=2.5e-07 median[50%]=5e-07 [75%]=7.5e-07
Jan 08 18:28:11 unbound[1445:0] info: lower(secs) upper(secs) recursions
Jan 08 18:28:11 unbound[1445:0] info:    0.000000    0.000001 86
Jan 08 18:28:11 unbound[1445:0] debug: cache memory msg=77779 rrset=66072 infra=7808 val=66368 subnet=74504

Along with this results on the query log:

The question now becomes:
I'm assuming the setup is not working. Knowing this, is it possible, safe or even recommended to keep using unbound as it is right now? Or should I just resort to using regular DNS?

Looking forward for recommendations.

Thanks!

Bucking_Horn · January 9, 2023, 7:44am

Your unbound seems to miss any valid forwarding configuration, i.e. it isn't aware of any upstream to forward DNSD requests to (I've strippped the timestamps for readability):

aamm19:

unbound[1445:0] debug:    ip6 fe80::1 port 53 (len 28)
unbound[1445:0] debug: attempt to get extra 3 targets
unbound[1445:0] debug: No more query targets, attempting last resort
unbound[1445:0] debug: configured stub or forward servers failed -- returning SERVFAIL
unbound[1445:0] debug: store error response in message cache
unbound[1445:0] debug: return error response SERVFAIL

unbound seems to be using fe80::1 (your router. likely) as its upstream resolver.
This may indicate that your router is not accepting DNS requests from unbound, or it may in turn have issues forwarding requests

But if you did follow our unbound guide, this shouldn't happen in the first place, as that would result in unbound running as a recursive resolver (talking to authoritative DNS servers directly) rather than a forwarding resolver (forwarding requests to some upstream).

What is the complete output of the following command from the Pi terminal:

sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*

aamm19 · January 9, 2023, 8:10am

Thanks for the response.

Here's the output of the command:

$ 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: "."
/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf:  forward-addr: fe80::1%eth0
/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:    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

If I understand correctly you're referring to the documentation part for disabling resolvconf, right?

Seems like I might've missed it on this last try of the setup, if it is, I'll give it a go.

The only part that it's not really clear to me is the one about domain_name_server= being propagated and what the value for that should be.

Bucking_Horn · January 9, 2023, 8:18am

There's also a chance that unbound's package installation messed up the configuration on Bullseye OS variants.

Try the following:

Edit file /etc/resolvconf.conf and comment out the last line which should then read:

#unbound_conf=/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf

Delete the unwanted unbound configuration file:

sudo rm /etc/unbound/unbound.conf.d/resolvconf_resolvers.conf

Restart unbound:

sudo service unbound restart

aamm19 · January 9, 2023, 8:25am

Thanks for the quick response

Restarted unbound after removing the resolvconf config:

$ sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*
/etc/unbound/unbound.conf:include-toplevel: "/etc/unbound/unbound.conf.d/*.conf"
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:server:
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:    auto-trust-anchor-file: "/var/lib/unbound/root.key"
/etc/unbound/unbound.conf.d/pi-hole.conf:server:
/etc/unbound/unbound.conf.d/pi-hole.conf:    logfile: "/var/log/unbound/unbound.log"
/etc/unbound/unbound.conf.d/pi-hole.conf:    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

logs for dig searx.net @127.0.0.1 -p 5335:

$ dig searx.net @127.0.0.1 -p 5335

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

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

;; Query time: 199 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Mon Jan 09 02:21:34 CST 2023
;; MSG SIZE  rcvd: 38

Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: start
Jan 09 02:21:34 unbound[6303:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Jan 09 02:21:34 unbound[6303:0] info: subnet operate: query searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: subnet: not found in cache. pass to next module
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: subnet module exit state is module_wait_module
Jan 09 02:21:34 unbound[6303:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Jan 09 02:21:34 unbound[6303:0] info: validator operate: query searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: validator: pass to next module
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: validator module exit state is module_wait_module
Jan 09 02:21:34 unbound[6303:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Jan 09 02:21:34 unbound[6303:0] debug: process_request: new external request event
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE
Jan 09 02:21:34 unbound[6303:0] info: resolving searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: request has dependency depth of 0
Jan 09 02:21:34 unbound[6303:0] debug: cache delegation returns delegpt
Jan 09 02:21:34 unbound[6303:0] info: DelegationPoint<.>: 13 names (7 missing), 19 addrs (0 result, 19 avail) cacheNS
Jan 09 02:21:34 unbound[6303:0] info:   i.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   a.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   j.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   f.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   h.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   b.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] info:   e.root-servers.net.  A
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Jan 09 02:21:34 unbound[6303:0] info: resolving (init part 2):  searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Jan 09 02:21:34 unbound[6303:0] info: resolving (init part 3):  searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Jan 09 02:21:34 unbound[6303:0] info: processQueryTargets: searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Jan 09 02:21:34 unbound[6303:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (0 result, 19 avail) cacheNS
Jan 09 02:21:34 unbound[6303:0] info:   i.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   a.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   j.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   f.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   h.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   b.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   e.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug: removing 1 labels
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Jan 09 02:21:34 unbound[6303:0] info: processQueryTargets: searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Jan 09 02:21:34 unbound[6303:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (0 result, 19 avail) cacheNS
Jan 09 02:21:34 unbound[6303:0] info:   i.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   a.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:21:34 unbound[6303:0] info:   j.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   f.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   h.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   b.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] info:   e.root-servers.net. * A
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug: attempt to get extra 3 targets
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=176 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=165 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=137 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=138 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=122 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=228 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=188 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=96 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=171 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=167 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=118 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=193 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug:    rtt=158 REC_LAME
Jan 09 02:21:34 unbound[6303:0] debug: selrtt 360096
Jan 09 02:21:34 unbound[6303:0] debug: chase to recursion lame server
Jan 09 02:21:34 unbound[6303:0] debug: chase to dnssec lame server
Jan 09 02:21:34 unbound[6303:0] info: sending query: searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: sending to target: <.> 199.7.91.13#53
Jan 09 02:21:34 unbound[6303:0] debug: dnssec status: expected but lame_query anyway
Jan 09 02:21:34 unbound[6303:0] debug: EDNS lookup known=1 vs=0
Jan 09 02:21:34 unbound[6303:0] debug: serviced query UDP timeout=137 msec
Jan 09 02:21:34 unbound[6303:0] debug: inserted new pending reply id=eb90
Jan 09 02:21:34 unbound[6303:0] debug: opened UDP if=0 port=4263
Jan 09 02:21:34 unbound[6303:0] debug: comm point start listening 17 (-1 msec)
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: iterator module exit state is module_wait_reply
Jan 09 02:21:34 unbound[6303:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 16 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 09 02:21:34 unbound[6303:0] info: average recursion processing time 0.114416 sec
Jan 09 02:21:34 unbound[6303:0] info: histogram of recursion processing times
Jan 09 02:21:34 unbound[6303:0] info: [25%]=0.016384 median[50%]=0.065536 [75%]=0.229376
Jan 09 02:21:34 unbound[6303:0] info: lower(secs) upper(secs) recursions
Jan 09 02:21:34 unbound[6303:0] info:    0.000000    0.000001 3
Jan 09 02:21:34 unbound[6303:0] info:    0.008192    0.016384 1
Jan 09 02:21:34 unbound[6303:0] info:    0.016384    0.032768 1
Jan 09 02:21:34 unbound[6303:0] info:    0.032768    0.065536 3
Jan 09 02:21:34 unbound[6303:0] info:    0.065536    0.131072 1
Jan 09 02:21:34 unbound[6303:0] info:    0.131072    0.262144 4
Jan 09 02:21:34 unbound[6303:0] info:    0.262144    0.524288 3
Jan 09 02:21:34 unbound[6303:0] info: 0RDd mod2 rep searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: cache memory msg=76038 rrset=79568 infra=11669 val=66537 subnet=74504
Jan 09 02:21:34 unbound[6303:0] debug: timeout udp
Jan 09 02:21:34 unbound[6303:0] debug: try edns1xx0 <searx.net.> 199.7.91.13#53
Jan 09 02:21:34 unbound[6303:0] debug: EDNS lookup known=1 vs=0
Jan 09 02:21:34 unbound[6303:0] debug: serviced query UDP timeout=137 msec
Jan 09 02:21:34 unbound[6303:0] debug: inserted new pending reply id=9bae
Jan 09 02:21:34 unbound[6303:0] debug: opened UDP if=0 port=63516
Jan 09 02:21:34 unbound[6303:0] debug: comm point start listening 18 (-1 msec)
Jan 09 02:21:34 unbound[6303:0] debug: close of port 4263
Jan 09 02:21:34 unbound[6303:0] debug: close fd 17
Jan 09 02:21:34 unbound[6303:0] debug: answer cb
Jan 09 02:21:34 unbound[6303:0] debug: Incoming reply id = 9bae
Jan 09 02:21:34 unbound[6303:0] debug: Incoming reply addr = ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:21:34 unbound[6303:0] debug: lookup size is 1 entries
Jan 09 02:21:34 unbound[6303:0] debug: received udp reply.
Jan 09 02:21:34 unbound[6303:0] debug: udp message[43:0] 9BAE81800001000100000000057365617278036E65740000010001C00C000100010000012C000440BE3F6F
Jan 09 02:21:34 unbound[6303:0] debug: outnet handle udp reply
Jan 09 02:21:34 unbound[6303:0] debug: measured roundtrip at 48 msec
Jan 09 02:21:34 unbound[6303:0] debug: svcd callbacks start
Jan 09 02:21:34 unbound[6303:0] debug: worker svcd callback for qstate 0x55a63056c0
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: start
Jan 09 02:21:34 unbound[6303:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Jan 09 02:21:34 unbound[6303:0] info: iterator operate: query searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: process_response: new external response event
Jan 09 02:21:34 unbound[6303:0] info: scrub for . NS IN
Jan 09 02:21:34 unbound[6303:0] info: response for searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] info: reply from <.> 199.7.91.13#53
Jan 09 02:21:34 unbound[6303:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
searx.net.      IN      A

;; ANSWER SECTION:
searx.net.      300     IN      A       64.190.63.111

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 43

Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Jan 09 02:21:34 unbound[6303:0] info: query response was ANSWER
Jan 09 02:21:34 unbound[6303:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Jan 09 02:21:34 unbound[6303:0] info: finishing processing for searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: iterator module exit state is module_finished
Jan 09 02:21:34 unbound[6303:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Jan 09 02:21:34 unbound[6303:0] info: validator operate: query searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: validator: nextmodule returned
Jan 09 02:21:34 unbound[6303:0] debug: val handle processing q with state VAL_INIT_STATE
Jan 09 02:21:34 unbound[6303:0] debug: validator classification positive
Jan 09 02:21:34 unbound[6303:0] info: no signer, using searx.net. TYPE0 CLASS0
Jan 09 02:21:34 unbound[6303:0] debug: val handle processing q with state VAL_FINISHED_STATE
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: validator module exit state is module_finished
Jan 09 02:21:34 unbound[6303:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Jan 09 02:21:34 unbound[6303:0] info: subnet operate: query searx.net. A IN
Jan 09 02:21:34 unbound[6303:0] debug: mesh_run: subnet module exit state is module_finished
Jan 09 02:21:34 unbound[6303:0] debug: query took 0.196850 sec
Jan 09 02:21:34 unbound[6303:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 17 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 09 02:21:34 unbound[6303:0] info: average recursion processing time 0.119265 sec
Jan 09 02:21:34 unbound[6303:0] info: histogram of recursion processing times
Jan 09 02:21:34 unbound[6303:0] info: [25%]=0.02048 median[50%]=0.098304 [75%]=0.229376
Jan 09 02:21:34 unbound[6303:0] info: lower(secs) upper(secs) recursions
Jan 09 02:21:34 unbound[6303:0] info:    0.000000    0.000001 3
Jan 09 02:21:34 unbound[6303:0] info:    0.008192    0.016384 1
Jan 09 02:21:34 unbound[6303:0] info:    0.016384    0.032768 1
Jan 09 02:21:34 unbound[6303:0] info:    0.032768    0.065536 3
Jan 09 02:21:34 unbound[6303:0] info:    0.065536    0.131072 1
Jan 09 02:21:34 unbound[6303:0] info:    0.131072    0.262144 5
Jan 09 02:21:34 unbound[6303:0] info:    0.262144    0.524288 3
Jan 09 02:21:34 unbound[6303:0] debug: cache memory msg=76289 rrset=79809 infra=11669 val=66537 subnet=74504
Jan 09 02:21:34 unbound[6303:0] debug: svcd callbacks end
Jan 09 02:21:34 unbound[6303:0] debug: close of port 63516
Jan 09 02:21:34 unbound[6303:0] debug: close fd 18

Still showing as bogus on the query log screen

Bucking_Horn · January 9, 2023, 8:50am

That's looking better:
Your log shows that unbound is now operating as recursive resolver, walking the chain of authoritative servers and returning the correct IP:

But obviously, unbound is withholding that reply from you for some reason.

What's the following command returning for you?

delv searx.net @127.0.0.1 -p 5335

; unsigned answer
searx.net.              3200171710 IN   A       64.190.63.111

aamm19 · January 9, 2023, 9:00am

I'm not sure if the logs for delv and dig have differences in them on unbound, but I'll still paste it anyways:

$ delv searx.net @127.0.0.1 -p 5335
;; resolution failed: SERVFAIL

Jan 09 02:57:13 unbound[6303:0] debug: answer from the cache failed
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: start
Jan 09 02:57:13 unbound[6303:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Jan 09 02:57:13 unbound[6303:0] info: subnet operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: subnet: not found in cache. pass to next module
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: subnet module exit state is module_wait_module
Jan 09 02:57:13 unbound[6303:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Jan 09 02:57:13 unbound[6303:0] info: validator operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: validator: pass to next module
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: validator module exit state is module_wait_module
Jan 09 02:57:13 unbound[6303:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Jan 09 02:57:13 unbound[6303:0] debug: process_request: new external request event
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE
Jan 09 02:57:13 unbound[6303:0] info: resolving searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: request has dependency depth of 0
Jan 09 02:57:13 unbound[6303:0] debug: cache delegation returns delegpt
Jan 09 02:57:13 unbound[6303:0] info: DelegationPoint<.>: 13 names (7 missing), 19 addrs (0 result, 19 avail) cacheNS
Jan 09 02:57:13 unbound[6303:0] info:   i.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   a.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   j.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   f.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   h.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   b.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] info:   e.root-servers.net.  A
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Jan 09 02:57:13 unbound[6303:0] info: resolving (init part 2):  searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Jan 09 02:57:13 unbound[6303:0] info: resolving (init part 3):  searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Jan 09 02:57:13 unbound[6303:0] info: processQueryTargets: searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Jan 09 02:57:13 unbound[6303:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (0 result, 19 avail) cacheNS
Jan 09 02:57:13 unbound[6303:0] info:   i.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   a.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   j.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   f.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   h.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   b.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   e.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug: removing 1 labels
Jan 09 02:57:13 unbound[6303:0] debug: attempt to get extra 3 targets
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=92 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=103 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=78 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=95 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=102 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=105 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=103 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=77 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=112 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=87 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=63 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=602 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=91 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: selrtt 360063
Jan 09 02:57:13 unbound[6303:0] debug: chase to recursion lame server
Jan 09 02:57:13 unbound[6303:0] debug: chase to dnssec lame server
Jan 09 02:57:13 unbound[6303:0] info: sending query: net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: sending to target: <.> 193.0.14.129#53
Jan 09 02:57:13 unbound[6303:0] debug: dnssec status: expected but lame_query anyway
Jan 09 02:57:13 unbound[6303:0] debug: EDNS lookup known=1 vs=0
Jan 09 02:57:13 unbound[6303:0] debug: serviced query UDP timeout=105 msec
Jan 09 02:57:13 unbound[6303:0] debug: inserted new pending reply id=5d2f
Jan 09 02:57:13 unbound[6303:0] debug: opened UDP if=0 port=23978
Jan 09 02:57:13 unbound[6303:0] debug: comm point start listening 17 (-1 msec)
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: iterator module exit state is module_wait_reply
Jan 09 02:57:13 unbound[6303:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 236 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 09 02:57:13 unbound[6303:0] info: average recursion processing time 0.104149 sec
Jan 09 02:57:13 unbound[6303:0] info: histogram of recursion processing times
Jan 09 02:57:13 unbound[6303:0] info: [25%]=0.009216 median[50%]=0.0320708 [75%]=0.184209
Jan 09 02:57:13 unbound[6303:0] info: lower(secs) upper(secs) recursions
Jan 09 02:57:13 unbound[6303:0] info:    0.000000    0.000001 57
Jan 09 02:57:13 unbound[6303:0] info:    0.008192    0.016384 16
Jan 09 02:57:13 unbound[6303:0] info:    0.016384    0.032768 47
Jan 09 02:57:13 unbound[6303:0] info:    0.032768    0.065536 30
Jan 09 02:57:13 unbound[6303:0] info:    0.065536    0.131072 12
Jan 09 02:57:13 unbound[6303:0] info:    0.131072    0.262144 37
Jan 09 02:57:13 unbound[6303:0] info:    0.262144    0.524288 36
Jan 09 02:57:13 unbound[6303:0] info:    0.524288    1.000000 1
Jan 09 02:57:13 unbound[6303:0] info: 0RDd mod2 rep searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: cache memory msg=97174 rrset=100180 infra=11669 val=66537 subnet=74504
Jan 09 02:57:13 unbound[6303:0] debug: answer cb
Jan 09 02:57:13 unbound[6303:0] debug: Incoming reply id = 5d2f
Jan 09 02:57:13 unbound[6303:0] debug: Incoming reply addr = ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug: lookup size is 1 entries
Jan 09 02:57:13 unbound[6303:0] debug: received udp reply.
Jan 09 02:57:13 unbound[6303:0] debug: udp message[94:0] 5D2F81800001000000010000036E65740000010001C00C0006000100000271003D01610C67746C642D73657276657273C00C056E73746C640C766572697369676E2D67727303636F6D0063BBD5BF000007080000038400093A8000015180
Jan 09 02:57:13 unbound[6303:0] debug: outnet handle udp reply
Jan 09 02:57:13 unbound[6303:0] debug: measured roundtrip at 11 msec
Jan 09 02:57:13 unbound[6303:0] debug: svcd callbacks start
Jan 09 02:57:13 unbound[6303:0] debug: worker svcd callback for qstate 0x55a62fd6a0
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: start
Jan 09 02:57:13 unbound[6303:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Jan 09 02:57:13 unbound[6303:0] info: iterator operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: process_response: new external response event
Jan 09 02:57:13 unbound[6303:0] info: scrub for . NS IN
Jan 09 02:57:13 unbound[6303:0] info: response for searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] info: reply from <.> 193.0.14.129#53
Jan 09 02:57:13 unbound[6303:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0 
;; QUESTION SECTION:
net.    IN      A

;; ANSWER SECTION:

;; AUTHORITY SECTION:
net.    625     IN      SOA     a.gtld-servers.net. nstld.verisign-grs.com. 1673254335 1800 900 604800 86400

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 94

Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Jan 09 02:57:13 unbound[6303:0] info: query response was nodata ANSWER
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Jan 09 02:57:13 unbound[6303:0] info: processQueryTargets: searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 1
Jan 09 02:57:13 unbound[6303:0] info: DelegationPoint<.>: 13 names (0 missing), 19 addrs (19 result, 0 avail) cacheNS
Jan 09 02:57:13 unbound[6303:0] info:   i.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   a.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   d.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   l.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   g.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   k.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   c.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   m.root-servers.net. * A AAAA
Jan 09 02:57:13 unbound[6303:0] info:   j.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   f.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   h.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   b.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] info:   e.root-servers.net. * A
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:dc3::35 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2::c port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:7fd::1 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:12::d0d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:9f::42 port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip6 2001:500:2d::d port 53 (len 28)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug: attempt to get extra 3 targets
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.203.230.10 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=91 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 198.97.190.53 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=63 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.5.5.241 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=87 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.58.128.30 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=112 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 202.12.27.33 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=77 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.33.4.12 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=103 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 193.0.14.129 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=100 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.112.36.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=102 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.7.83.42 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=95 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=78 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 198.41.0.4 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=103 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 192.36.148.17 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=92 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: servselect ip4 199.9.14.201 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug:    rtt=602 REC_LAME
Jan 09 02:57:13 unbound[6303:0] debug: selrtt 360063
Jan 09 02:57:13 unbound[6303:0] debug: chase to recursion lame server
Jan 09 02:57:13 unbound[6303:0] debug: chase to dnssec lame server
Jan 09 02:57:13 unbound[6303:0] info: sending query: searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: sending to target: <.> 199.7.91.13#53
Jan 09 02:57:13 unbound[6303:0] debug: dnssec status: expected but lame_query anyway
Jan 09 02:57:13 unbound[6303:0] debug: EDNS lookup known=1 vs=0
Jan 09 02:57:13 unbound[6303:0] debug: serviced query UDP timeout=78 msec
Jan 09 02:57:13 unbound[6303:0] debug: inserted new pending reply id=98f2
Jan 09 02:57:13 unbound[6303:0] debug: opened UDP if=0 port=44242
Jan 09 02:57:13 unbound[6303:0] debug: comm point start listening 18 (-1 msec)
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: iterator module exit state is module_wait_reply
Jan 09 02:57:13 unbound[6303:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 236 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 09 02:57:13 unbound[6303:0] info: average recursion processing time 0.104149 sec
Jan 09 02:57:13 unbound[6303:0] info: histogram of recursion processing times
Jan 09 02:57:13 unbound[6303:0] info: [25%]=0.009216 median[50%]=0.0320708 [75%]=0.184209
Jan 09 02:57:13 unbound[6303:0] info: lower(secs) upper(secs) recursions
Jan 09 02:57:13 unbound[6303:0] info:    0.000000    0.000001 57
Jan 09 02:57:13 unbound[6303:0] info:    0.008192    0.016384 16
Jan 09 02:57:13 unbound[6303:0] info:    0.016384    0.032768 47
Jan 09 02:57:13 unbound[6303:0] info:    0.032768    0.065536 30
Jan 09 02:57:13 unbound[6303:0] info:    0.065536    0.131072 12
Jan 09 02:57:13 unbound[6303:0] info:    0.131072    0.262144 37
Jan 09 02:57:13 unbound[6303:0] info:    0.262144    0.524288 36
Jan 09 02:57:13 unbound[6303:0] info:    0.524288    1.000000 1
Jan 09 02:57:13 unbound[6303:0] info: 0RDd mod2 rep searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: cache memory msg=97174 rrset=100180 infra=11669 val=66537 subnet=74504
Jan 09 02:57:13 unbound[6303:0] debug: svcd callbacks end
Jan 09 02:57:13 unbound[6303:0] debug: close of port 23978
Jan 09 02:57:13 unbound[6303:0] debug: close fd 17
Jan 09 02:57:13 unbound[6303:0] debug: timeout udp
Jan 09 02:57:13 unbound[6303:0] debug: try edns1xx0 <searx.net.> 199.7.91.13#53
Jan 09 02:57:13 unbound[6303:0] debug: EDNS lookup known=1 vs=0
Jan 09 02:57:13 unbound[6303:0] debug: serviced query UDP timeout=78 msec
Jan 09 02:57:13 unbound[6303:0] debug: inserted new pending reply id=904d
Jan 09 02:57:13 unbound[6303:0] debug: opened UDP if=0 port=21088
Jan 09 02:57:13 unbound[6303:0] debug: comm point start listening 17 (-1 msec)
Jan 09 02:57:13 unbound[6303:0] debug: close of port 44242
Jan 09 02:57:13 unbound[6303:0] debug: close fd 18
Jan 09 02:57:13 unbound[6303:0] debug: answer cb
Jan 09 02:57:13 unbound[6303:0] debug: Incoming reply id = 904d
Jan 09 02:57:13 unbound[6303:0] debug: Incoming reply addr = ip4 199.7.91.13 port 53 (len 16)
Jan 09 02:57:13 unbound[6303:0] debug: lookup size is 1 entries
Jan 09 02:57:13 unbound[6303:0] debug: received udp reply.
Jan 09 02:57:13 unbound[6303:0] debug: udp message[43:0] 904D81800001000100000000057365617278036E65740000010001C00C000100010000012C000440BE3F6F
Jan 09 02:57:13 unbound[6303:0] debug: outnet handle udp reply
Jan 09 02:57:13 unbound[6303:0] debug: measured roundtrip at 27 msec
Jan 09 02:57:13 unbound[6303:0] debug: svcd callbacks start
Jan 09 02:57:13 unbound[6303:0] debug: worker svcd callback for qstate 0x55a62fd6a0
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: start
Jan 09 02:57:13 unbound[6303:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Jan 09 02:57:13 unbound[6303:0] info: iterator operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: process_response: new external response event
Jan 09 02:57:13 unbound[6303:0] info: scrub for . NS IN
Jan 09 02:57:13 unbound[6303:0] info: response for searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] info: reply from <.> 199.7.91.13#53
Jan 09 02:57:13 unbound[6303:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
searx.net.      IN      A

;; ANSWER SECTION:
searx.net.      300     IN      A       64.190.63.111

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:
;; MSG SIZE  rcvd: 43

Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Jan 09 02:57:13 unbound[6303:0] info: query response was ANSWER
Jan 09 02:57:13 unbound[6303:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Jan 09 02:57:13 unbound[6303:0] info: finishing processing for searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: iterator module exit state is module_finished
Jan 09 02:57:13 unbound[6303:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Jan 09 02:57:13 unbound[6303:0] info: validator operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: validator: nextmodule returned
Jan 09 02:57:13 unbound[6303:0] debug: val handle processing q with state VAL_INIT_STATE
Jan 09 02:57:13 unbound[6303:0] debug: validator classification positive
Jan 09 02:57:13 unbound[6303:0] info: no signer, using searx.net. TYPE0 CLASS0
Jan 09 02:57:13 unbound[6303:0] debug: val handle processing q with state VAL_FINISHED_STATE
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: validator module exit state is module_finished
Jan 09 02:57:13 unbound[6303:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Jan 09 02:57:13 unbound[6303:0] info: subnet operate: query searx.net. A IN
Jan 09 02:57:13 unbound[6303:0] debug: mesh_run: subnet module exit state is module_finished
Jan 09 02:57:13 unbound[6303:0] debug: query took 0.121339 sec
Jan 09 02:57:13 unbound[6303:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 237 recursion replies sent, 0 replies dropped, 0 states jostled out
Jan 09 02:57:13 unbound[6303:0] info: average recursion processing time 0.104222 sec
Jan 09 02:57:13 unbound[6303:0] info: histogram of recursion processing times
Jan 09 02:57:13 unbound[6303:0] info: [25%]=0.009344 median[50%]=0.0322451 [75%]=0.183324
Jan 09 02:57:13 unbound[6303:0] info: lower(secs) upper(secs) recursions
Jan 09 02:57:13 unbound[6303:0] info:    0.000000    0.000001 57
Jan 09 02:57:13 unbound[6303:0] info:    0.008192    0.016384 16
Jan 09 02:57:13 unbound[6303:0] info:    0.016384    0.032768 47
Jan 09 02:57:13 unbound[6303:0] info:    0.032768    0.065536 30
Jan 09 02:57:13 unbound[6303:0] info:    0.065536    0.131072 13
Jan 09 02:57:13 unbound[6303:0] info:    0.131072    0.262144 37
Jan 09 02:57:13 unbound[6303:0] info:    0.262144    0.524288 36
Jan 09 02:57:13 unbound[6303:0] info:    0.524288    1.000000 1
Jan 09 02:57:13 unbound[6303:0] debug: cache memory msg=97174 rrset=100180 infra=11669 val=66537 subnet=74504
Jan 09 02:57:13 unbound[6303:0] debug: svcd callbacks end
Jan 09 02:57:13 unbound[6303:0] debug: close of port 21088
Jan 09 02:57:13 unbound[6303:0] debug: close fd 17

EDIT:
I tried the same against 8.8.8.8 and got a different result:

$ delv searx.net @8.8.8.8
;; no valid RRSIG resolving 'net/DS/IN': 8.8.8.8#53
;; broken trust chain resolving 'searx.net/A/IN': 8.8.8.8#53
;; resolution failed: broken trust chain
$ delv searx.net @127.0.0.1 -p 5335
;; resolution failed: SERVFAIL

I also checked ping but it's not resolving:

$ ping google.com
ping: google.com: Temporary failure in name resolution

Bucking_Horn · January 9, 2023, 10:05am

The interesing part in both of your most recent unbound logs is this:

As my delv results show that searx.net isn't DNSSEC signed, it seems expected that unbound is reporting a similar observation, but then your unbound seems to fail when trying to refer to the respective subdomain.

That may indicate that something upstream of your network is interfering with DNS resolution.

This seems all the more likely as I have no issues resolving searx.net via unbound nor via Google's resolvers with DNSSEC validation:

~$ delv searx.net @127.0.0.1 -p 5335
; unsigned answer
searx.net.              3200171710 IN   A       64.190.63.111
~$ delv searx.net @8.8.8.8
; unsigned answer
searx.net.              3200171710 IN   A       64.190.63.111

Are you perhaps utilising a VPN provider to channel all your network's public Internet traffic?

system · January 30, 2023, 10:06am

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