My original reply was rejected by the server (I think) as I included too
much log data. Apologies this gets posted twice.
Can you show the work that it does for looking up one of the root
servers? Not getting an address must be causing it to not have
content.
But it does work (eventually), you say, once the long list appears,
that means the AXFR has completed. Meanwhile you should have normal
service, because the zone is loaded (the file that is configured has
content, right?)? When a normal query arrives, it should just be
answered with the auth-zone?
Detailed log of lookups included below. I would like to add that the
issue may be associated specifically be the lookup of the auth-zone
domain names. At work, I use unbound as a local caching server on my
laptop, with a similar configuration as my home router, but I used IP
addresses instead of hostnames, and I have not had any problems with it
(this might be a useful work-around to try for anyone who still want to
use the auth-zone functionality):
auth-zone:
name: "."
master: 193.0.14.129 # k.root-servers.net
master: 192.112.36.4 # g.root-servers.net
master: 2001:500:2f::f # f.root-servers.net
master: 2001:500:84::b # b.root-servers.net
master: 192.0.47.132 # xfr.cjr.dns.icann.org
master: 2001:7fd::1 # k.root-servers.net
master: 192.0.32.132 # xfr.lax.dns.icann.org
master: 192.33.4.12 # c.root-servers.net
master: 2620:0:2830:202::132 # xfr.cjr.dns.icann.org
master: 2620:0:2d0:202::132 # xfr.lax.dns.icann.org
master: 192.228.79.201 # b.root-servers.net
master: 192.5.5.241 # f.root-servers.net
fallback-enabled: yes
for-downstream: no
for-upstream: yes
zonefile: root.zone
Looking at the logs again, I noticed there was one incident of a
dropped query ~15min before all queries start to fail. However, that
query ends up completing, I think, and at 14:43:40 a different query
goes through without issue. It's at 15:00 that queries begin to fail.
I don't know if this error before the root server lookup is part of
the cause or a red herring.
May 18 14:43:35 homebrew unbound[30620]: [30620:0] info: 0RDd mod1 rep
www.google.com. AAAA IN
May 18 14:43:35 homebrew unbound[30620]: [30620:0] info: 1RDd mod1 rep
connectivitycheck.gstatic.com. AAAA IN
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: cache memory
msg=382505 rrset=462002 infra=7600 val=135128
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: answer from
the cache failed
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: udp request
from ip4 192.168.0.154 port 64667 (len 16)
May 18 14:43:35 homebrew unbound[30620]: [30620:0] warning: No jostle
attempt. m=(nil) # <= This is logging I added to find out which if
condition is failing
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: Too many
queries. dropping incoming query.
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: cache memory
msg=382505 rrset=462002 infra=7600 val=135128
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: comm point
listen_for_rw 15 0
May 18 14:43:35 homebrew unbound[30620]: [30620:0] debug: comm point
listen_for_rw 16 0
*Log of root server lookups below. Note that this occurs when I am not
home, with a single tablet as the only active device, so it's not that
there's a large amount of traffic or anything like that.
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: auth zone .:
master lookup for task_probe b.root-servers.net. A IN
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: mesh_run:
start
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug:
validator[module 0] operate: extstate:module_state_initial
event:module_event_new
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: validator
operate: query b.root-servers.net. A IN
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: validator:
pass to next module
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: mesh_run:
validator module exit state is module_wait_module
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug:
iterator[module 1] operate: extstate:module_state_initial
event:module_event_pass
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug:
process_request: new external request event
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: iter_handle
processing q with state INIT REQUEST STATE
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: resolving
b.root-servers.net. A IN
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: request has
dependency depth of 0
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: msg from cache
lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr rd ra ; QUERY: 1,
ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
b.root-servers.net. IN
A
;; ANSWER SECTION:
b.root-servers.net.
1841075 IN A 199.9.14.201
;; AUTHORITY SECTION:
;; ADDITIONAL SECTION:
;; MSG SIZE rcvd: 52
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: msg ttl is
41390, prefetch ttl 32750
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: returning
answer from cache.
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: iter_handle
processing q with state FINISHED RESPONSE STATE
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: finishing
processing for b.root-servers.net. A IN
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: mesh_run:
iterator module exit state is module_finished
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug:
validator[module 0] operate: extstate:module_wait_module
event:module_event_moddone
May 18 14:59:11 homebrew unbound[30620]: [30620:0] info: validator
operate: query b.root-servers.net. A IN
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: validator:
nextmodule returned
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: response has
already been validated: sec_status_insecure
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: mesh_run:
validator module exit state is module_finished
May 18 14:59:11 homebrew unbound[30620]: [30620:0] debug: auth host
b.root-servers.net lookup 199.9.14.201
