As of now, it's been trying to query the debian ntp server but failing to do so
Needless to say, timedatectl now shows it's unsynched
aamm19@pihole:~ $ timedatectl
Local time: Sun 2022-12-04 15:09:19 CST
Universal time: Sun 2022-12-04 21:09:19 UTC
RTC time: n/a
Time zone: America/Monterrey (CST, -0600)
System clock synchronized: no
NTP service: active
RTC in local TZ: no
This are the results on pihole.log
My apologies, I forgot to add that Settings > DNS > Use DNSSEC needs to be ticked and then scroll down and click Save. This allows Pi-hole to show the DNSSEC results in the Query Log too. You'll then normally see SECURE where DNSSEC is available and working, or INSECURE where DNSSEC isn't available, or sometimes various errors like BOGUS showing that DNSSEC failed.
This did produce a different output, and some interesting things on it
query log:
192.180.100.100 is my computer
EDIT: 2 seconds after I post this, additional output appeared:
Hi,
Just sending an update on this whole issue, I've been sitting on it for a couple of days, still getting bogus responses on requests.
One piece of info that is showing on the unbound.log is the following
Dec 06 08:31:20 unbound[539:0] info: validation failure <dealer.spotify.com. A IN>: key for validation . is marked as invalid because of a previous validation failure <1.debian.pool.ntp.org. AAAA IN>: no signatures from 192.5.5.241 for trust anchor . while building chain of trust
Just posting it as to not let the thread die and also for ideas on what the issue could be.
This still looks like a timing issue.
DNSSEC validation would fail without correct time, and it would fail so already with the root servers.
Your recent log excerpts are consistent with that:
192.5.5.241 is one of the DNS root servers.
Your Pi-hole logs also suggest your system tries to acquire accurate time information through *.pool.ntp.org resources, but fails to resolve the respective domains, presumably due to incorrect timings.
What hardware do you run your Pi-hole on?
Does that feature a battery-backed RTC?
If not, consider fitting one.
If fitting an RTC is not an option, try configuring your Pi-hole host OS to use your router's IP as primary NTP server (provided your router supports that).
If that's also not an option, you could apply a dnsmasq custom configuration to forward requests for *.pool.ntp.org specfically to your router (e.g. server=/pool.ntp.org/<router_ip>), avoiding to involve unbound and DNSSEC validation.
Thanks for the response @Bucking_Horn,
To be completely honest, I'm still fairly new to the usage of Rasperries in general. I'll look into sourcing an RTC module if that'll make my life easier.
As for the option of using my router as an NTP server, is there a way I can verify this? I've logged into the router before but don't recall any option on time/ntp settings.
I'll look into the dnsmasq customization as well and keep posting any issues.
I cannot know that (unless it would be a FritzBox model similar to the one that I am using 
).
Your router's documentaion and support channels should have the details.
In the meantime:
If you opt for that:
Create and edit a custom dnsmasq configuration file, e.g.
sudo nano /etc/dnsmasq.d/42-pool-ntp-org-forward.conf
Add the following lines
# forward requests for NTP server names to be resolved by my router's IP
server=/pool.ntp.org/192.168.0.1
Of course, replace 192.168.0.1 with your router's IPv4 address.
Then run a dnsmasq syntax check:
pihole-FTL dnsmasq-test
If ok, restart Pi-hole:
pihole restartdns
Hello internet.
I am back! Now with a DS3231 RTC ( Adafruit DS3231 Precision RTC Breakout) to test with!
I'll redo the whole setup later today along with research on how to configure the RTC and will provide an update.
Here's an update
I basically redid the whole setup focusing on setting up the RTC and doing a clean install of Pi-hole and unbound.
I followed the same steps as before and verified the trust anchor
aamm19@pihole:~ $ sudo -u unbound unbound-anchor -v
/var/lib/unbound/root.key has content
success: the anchor is ok
As well as configured the DNSSEC to be shown as per @chrislph's suggestion.
Current results:
aamm19@pihole:~ $ dig dnssec.works @127.0.0.1
; <<>> DiG 9.16.33-Debian <<>> dnssec.works @127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 38620
;; 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: 139 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Thu Dec 15 20:12:45 CST 2022
;; MSG SIZE rcvd: 41
aamm19@pihole:~ $ dig dnssec.works @8.8.4.4
; <<>> DiG 9.16.33-Debian <<>> dnssec.works @8.8.4.4
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 64638
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;dnssec.works. IN A
;; ANSWER SECTION:
dnssec.works. 2940 IN A 5.45.107.88
;; Query time: 7 msec
;; SERVER: 8.8.4.4#53(8.8.4.4)
;; WHEN: Thu Dec 15 20:12:54 CST 2022
;; MSG SIZE rcvd: 46
aamm19@pihole:~ $ timedatectl
Local time: Thu 2022-12-15 20:13:07 CST
Universal time: Fri 2022-12-16 02:13:07 UTC
RTC time: Fri 2022-12-16 02:13:07
Time zone: America/Monterrey (CST, -0600)
System clock synchronized: yes
NTP service: active
RTC in local TZ: no
unbound.log (partial)
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: start
Dec 15 20:19:18 unbound[15005:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 15 20:19:18 unbound[15005:0] info: iterator operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: process_response: new external response event
Dec 15 20:19:18 unbound[15005:0] info: scrub for . NS IN
Dec 15 20:19:18 unbound[15005:0] info: response for _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] info: reply from <.> 192.168.100.1#53
Dec 15 20:19:18 unbound[15005:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
;; QUESTION SECTION:
_ta-4f66. IN NULL
;; ANSWER SECTION:
;; AUTHORITY SECTION:
. 3600 IN SOA a.root-servers.net. nstld.verisign-grs.com. 2022121501 1800 900 604800 86400
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 101
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: query response was NXDOMAIN ANSWER
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: finishing processing for _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: iterator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: validator: nextmodule returned
Dec 15 20:19:18 unbound[15005:0] debug: not validating response, is valrec(validation recursion lookup)
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query _ta-4f66. NULL IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] info: mesh_run: end 2 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 15 20:19:18 unbound[15005:0] info: 0vRDCD mod2 . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: 1RDdc mod1 rep dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: cache memory msg=66817 rrset=67388 infra=8105 val=66368 subnet=74504
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks end
Dec 15 20:19:18 unbound[15005:0] debug: close of port 17371
Dec 15 20:19:18 unbound[15005:0] debug: close fd 14
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: outnettcp cb
Dec 15 20:19:18 unbound[15005:0] debug: outnet tcp pkt was written event
Dec 15 20:19:18 unbound[15005:0] debug: outnet tcp writes done, wait
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: comm point start listening 12 (60000 msec)
Dec 15 20:19:18 unbound[15005:0] debug: Reading tcp query of length 567
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: outnettcp cb
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks start
Dec 15 20:19:18 unbound[15005:0] debug: worker svcd callback for qstate 0x558d2739b0
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: start
Dec 15 20:19:18 unbound[15005:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Dec 15 20:19:18 unbound[15005:0] info: iterator operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: process_response: new external response event
Dec 15 20:19:18 unbound[15005:0] info: scrub for . NS IN
Dec 15 20:19:18 unbound[15005:0] info: response for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: reply from <.> 192.168.100.1#53
Dec 15 20:19:18 unbound[15005:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
. IN DNSKEY
;; ANSWER SECTION:
. 86400 IN DNSKEY 257 3 8 AwEAAaz/tAm8yTn4Mfeh5eyI96WSVexTBAvkMgJzkKTOiW1vkIbzxeF3+/4RgWOq7HrxRixHlFlExOLAJr5emLvN7SWXgnLh4+B5xQlNVz8Og8kvArMtNROxVQuCaSnIDdD5LKyWbRd2n9WGe2R8PzgCmr3EgVLrjyBxWezF0jLHwVN8efS3rCj/EWgvIWgb9tarpVUDK/b58Da+sqqls3eNbuv7pr+eoZG+SrDK6nWeL3c6H5Apxz7LjVc1uTIdsIXxuOLYA4/ilBmSVIzuDWfdRUfhHdY6+cn8HFRm+2hM8AnXGXws9555KrUB5qihylGa8subX2Nn6UwNR1AkUTV74bU= ;{id = 20326 (ksk), size = 2048b}
. 86400 IN DNSKEY 256 3 8 AwEAAeB54o2xvW6vY4qQZ0krDsEZCe6MsRWCqsXd4+cNJZMePnlV/xwDrIbbeH1SJzv742rOHzgAKM1/3SQHHSkoEIPx8XQdHAZBxfhaXl3e8c5WrE3aGXS5AeTWAkt85ccqWgKyitxjFmJEOol0BqS2xueltaDwgWcC10nPUY+y5l/kTOYyptYQS4gg1uJNXIob/R1XIEJ10ZCurkYqZxgqyHc7tZv09N23o9rnGdjnYiArH7FjlXD8Rvjde8YWkmfdbCEWnchrnxDK8KV2/ZvBpG/WYnRKXYPUceGCw59OJdJ5M7utkm547RB3eEd8CVVhbXopZlsKq3GCrBwaIVe9ci0= ;{id = 18733 (zsk), size = 2048b}
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 567
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: query response was ANSWER
Dec 15 20:19:18 unbound[15005:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Dec 15 20:19:18 unbound[15005:0] info: finishing processing for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: iterator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: validator: nextmodule returned
Dec 15 20:19:18 unbound[15005:0] debug: not validating response, is valrec(validation recursion lookup)
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] info: validator: inform_super, sub is . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] info: super is dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] info: autotrust process for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: rrset failed to verify due to a lack of signatures
Dec 15 20:19:18 unbound[15005:0] debug: Failed to match any usable anchor to a DNSKEY.
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: validate DNSKEY with anchor: sec_status_bogus
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: dnskey did not verify.
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: write to disk: /var/lib/unbound/root.key.15005-0-558cc6da30
Dec 15 20:19:18 unbound[15005:0] debug: autotrust: replaced /var/lib/unbound/root.key
Dec 15 20:19:18 unbound[15005:0] debug: rrset failed to verify due to a lack of signatures
Dec 15 20:19:18 unbound[15005:0] debug: Failed to match any usable anchor to a DNSKEY.
Dec 15 20:19:18 unbound[15005:0] info: validate keys with anchor(DS): sec_status_bogus
Dec 15 20:19:18 unbound[15005:0] info: failed to prime trust anchor -- DNSKEY rrset is not secure . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Dec 15 20:19:18 unbound[15005:0] info: validator operate: query dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Dec 15 20:19:18 unbound[15005:0] info: Could not establish a chain of trust to keys for . DNSKEY IN
Dec 15 20:19:18 unbound[15005:0] debug: val handle processing q with state VAL_FINISHED_STATE
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: validator module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Dec 15 20:19:18 unbound[15005:0] info: subnet operate: query dnssec.works. A IN
Dec 15 20:19:18 unbound[15005:0] debug: mesh_run: subnet module exit state is module_finished
Dec 15 20:19:18 unbound[15005:0] debug: query took 0.150888 sec
Dec 15 20:19:18 unbound[15005:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
Dec 15 20:19:18 unbound[15005:0] info: average recursion processing time 0.150888 sec
Dec 15 20:19:18 unbound[15005:0] info: histogram of recursion processing times
Dec 15 20:19:18 unbound[15005:0] info: [25%]=0 median[50%]=0 [75%]=0
Dec 15 20:19:18 unbound[15005:0] info: lower(secs) upper(secs) recursions
Dec 15 20:19:18 unbound[15005:0] info: 0.131072 0.262144 1
Dec 15 20:19:18 unbound[15005:0] debug: cache memory msg=66817 rrset=67388 infra=8105 val=66537 subnet=74504
Dec 15 20:19:18 unbound[15005:0] debug: svcd callbacks end
Dec 15 20:19:18 unbound[15005:0] debug: comm point stop listening 12
Dec 15 20:19:18 unbound[15005:0] debug: comm point start listening 12 (60000 msec)
Pi-hole Query Log:
I might be missing any configuration or steps I did before so if you see anything different just let me know and I'll keep updating.
Hi @aamm19 did you get anywhere with this? Is it still behaving the same? It's clearly something to do with the section below – without the chain of trust from the root upwards, the result is flagged as BOGUS, hence Pi-hole reporting as "BOGUS (refused upstream)" where "upstream" in this case is simply a reference to Unbound.
But you've sorted your system clock and it's correct (from your paste) and your root file was also sorted, so I'm not sure how to interpret what Unbound is doing. I'm wondering if it's a permissions issue for the root key or something like that.
debug: autotrust: validate DNSKEY with anchor: sec_status_bogus debug: autotrust: dnskey did not verify. debug: autotrust: write to disk: /var/lib/unbound/root.key.15005-0-558cc6da30 debug: autotrust: replaced /var/lib/unbound/root.key debug: rrset failed to verify due to a lack of signatures debug: Failed to match any usable anchor to a DNSKEY.
Hi @chrislph, thanks for the follow-up! I did some testing a bit after that and disconnected the Raspberry-Pi for a couple of hours (both power and internet), but the clock seems to keeps getting the time off by a margin.
I'll try and repeat the setup and run through the motions these days to see if I can get this issue sorted out. It keeps bugging me something you pointed out towards the Authenticated Data part of the dig requests, It might even be blacklisting because of the number of requests or something (hopefully not haha)
Will update once I've finished the setup.
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!
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):
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*
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.
There's also a chance that unbound's package installation messed up the configuration on Bullseye OS variants.
Try the following:
/etc/resolvconf.conf and comment out the last line which should then read:#unbound_conf=/etc/unbound/unbound.conf.d/resolvconf_resolvers.conf
sudo rm /etc/unbound/unbound.conf.d/resolvconf_resolvers.conf
sudo service unbound restart
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
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
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
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?
This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.