I've been running Unbound happily for quite a while but today I found plenty of websites were not resolving. I found some error messages in the log about Unbound being unable to update the root key - turned out I hadn't installed unbound-anchor . Well, live and learn right?
Running unbound-anchor manually clearly spits out an error but my Google fu does not bring up anything significant. Any suggestions on how to further debug this?
root@OpenWrt:~# unbound-anchor -v
/var/lib/unbound/root.key has content
fail: the anchor is NOT ok and could not be fixed
Turning on debugging (verbosity 3 in /etc/config/unbound shows nothing obvious for me:
Unbound startup with debugging enabled
Fri Aug 19 23:33:19 2022 user.notice unbound: default recursion configuration
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: chdir to /var/lib/unbound
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: chroot to /var/lib/unbound
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: drop user privileges, run as unbound
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: module config: "validator iterator"
Fri Aug 19 23:33:20 2022 daemon.notice unbound: [5563:0] notice: init module 0: validator
Fri Aug 19 23:33:20 2022 daemon.notice unbound: [5563:0] notice: init module 1: iterator
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: target fetch policy for level 0 is 3
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: target fetch policy for level 1 is 2
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: target fetch policy for level 2 is 1
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: target fetch policy for level 3 is 0
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: target fetch policy for level 4 is 0
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: cache memory msg=16536 rrset=16536 infra=2048 val=16816
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: start of service (unbound 1.16.2).
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: validator operate: query . DNSKEY IN
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: resolving . DNSKEY IN
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: priming . IN NS
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: iterator operate: query . NS IN
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: processQueryTargets: . NS IN
Fri Aug 19 23:33:20 2022 daemon.info unbound: [5563:0] info: sending query: . NS IN
Fri Aug 19 23:33:20 2022 daemon.debug unbound: [5563:0] debug: sending to target: <.> 192.5.5.241#53
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_noreply
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: iterator operate: query . NS IN
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: processQueryTargets: . NS IN
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: sending query: . NS IN
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: sending to target: <.> 2001:500:9f::42#53
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: cache memory msg=16536 rrset=16536 infra=2345 val=16816
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_noreply
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: iterator operate: query . NS IN
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: processQueryTargets: . NS IN
Fri Aug 19 23:33:21 2022 daemon.info unbound: [5563:0] info: sending query: . NS IN
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: sending to target: <.> 193.0.14.129#53
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: cache memory msg=16536 rrset=16536 infra=2642 val=16816
Fri Aug 19 23:33:21 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_noreply
A bit later on though SERVFAILs will start to pop up (I suppose because DNS doesn't work...):
Debug log with SERVFAIL
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: request has exceeded the maximum number of sends with 33
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: return error response SERVFAIL
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: validator operate: query . NS IN
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: iterator operate: query 0.openwrt.pool.ntp.org. A IN
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: processQueryTargets: 0.openwrt.pool.ntp.org. A IN
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: Failed to get a delegation, giving up
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: return error response SERVFAIL
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: validator operate: query 0.openwrt.pool.ntp.org. A IN
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: iterator operate: query 0.openwrt.pool.ntp.org. AAAA IN
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: processQueryTargets: 0.openwrt.pool.ntp.org. AAAA IN
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: Failed to get a delegation, giving up
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: return error response SERVFAIL
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Fri Aug 19 23:33:50 2022 daemon.info unbound: [5563:0] info: validator operate: query 0.openwrt.pool.ntp.org. AAAA IN
Fri Aug 19 23:33:50 2022 daemon.debug unbound: [5563:0] debug: cache memory msg=16536 rrset=16536 infra=9770 val=16816
Setting an upstream DNS server (e.g. Quad9) on my clients makes them work again, and querying Unbound on my router makes the clients complain about DNS resolution, so it's clearly an Unbound issue. Any tips on how to proceed are appreciated
Yes - I've set the time manually before trying to update the anchor.
I've tried with the firewall stopped, I saw that DietPj
I post too, thanks. Did not make a difference unfortunately. Fact it's been working well for months (22.03 build with firewall4) suggests the firewall is not involved.
your unbound dns servers are accesed via port 53, or are accesed via port 853 or port 443??
because if accessed via port 853 or port 443 sometimes little time discrepancies prevents unbound from making dns connections.
so you need first make sure ntpd, is correctly giving the time to the router itself, I don't know the ntpd commands to sync time, I use chronyd but the recipe is:
disable the firewall to disable rules preventing port 53 access.
add nameserver 8.8.8.8 to /tmp/resolv.conf to bypass unbound
run ntp commands to sync time.
when you do have synced time restart unbound
but if your unbound access his dns server via port 53 I don't have any ideas, are you tried to:
mv /var/lib/unbound/root.key /var/lib/unbound/root.key.orig
vim /var/lib/unbound/root.key
I've disabled the firewall before, doesn't make a difference... Restarting the Busybox NTP daemon (sysntpd service) after setting the nameserver does make NTP sync, but no difference.
I've tried copying the contents of your root.key over, but it doesn't make a difference either. Appreciate the help though. Contents of my root.key:
# cat /var/lib/unbound/root.key
. IN DS 19036 8 2 49AAC11D7B6F6446702E54A1607371607A1A41855200FD2CE1CDDE32F24E8FB5
. IN DS 20326 8 2 E06D44B80B8F1D39A95C0B0D7C65D08458E880409BBC683457104237C7F8EC8D
Which turns out to be identical to the one part of the unbound-daemon package sitting in /etc/unbound/root.key. I'm able to work around it by configuring as a forwarding DNS server, but that defeats its purpose of course.
@gabrielo Sorry for sending you (and myself) on a fool's errand. I had my ISP install an ONT for fiber migration yesterday, and they cut the connection on the copper line for a few minutes but brought it back online, so I thought I should not migrate yet. That's when Unbound started acting up more or less.
I decided to take my chances this morning and switch to the fiber connection today, and lo and behold... Unbound is fully functional again, with a root key that makes sense:
. Well, live and learn right?