Hi,
First posted this to ServerFault without luck. Looks like it might be an
unbound bug, or am I doing something wrong?
***
This is a follow-up to
http://serverfault.com/questions/699094/unbound-nsd-returning-servfail-resolving-local-lan-dns-nsd-alone-works-fine/699124?noredirect=1#comment864282_699124
This *should* be a fairly simple DNS setup for my local home network.
unbound is a caching DNS server for normal use, and I'm using nsd for
systems specific to my network. I've set up unbound to proxy requests
for datanet.home to nsd, following what I've seen others do.
When I query nsd directly, it works fine.
$ dig @192.168.1.50 -p 53530 data1.datanet.home
[...]
;; ANSWER SECTION:
data1.datanet.home. 600 IN A 192.168.1.61
Querying via unbound (default port) yields a SERVFAIL.
$ dig @192.168.1.50 data1.datanet.home
[...]
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 36182
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
But the kicker is - going through the unbound logs with verbosity = 4,
and looking at the cache, it is clear that it *is* actually fetching the
result from nsd.
# unbound-control dump_cache | grep datanet
data1.datanet.home. 457 IN A 192.168.1.61
data2.datanet.home. 93 IN A 192.168.1.62
datanet.home. 93 IN NS ns1.datanet.home.
As far as unbound logs, there is a lot with verbosity=4, but this is
what appears directly under the part of the log where you can clearly
see that it got the correct answer from the upstream nsd:
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iter_handle processing q with state QUERY RESPONSE STATE
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
query response was ANSWER
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iter_handle processing q with state FINISHED RESPONSE STATE
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
finishing processing for data1.datanet.home. A IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
mesh_run: iterator module exit state is module_finished
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
validator[module 0] operate: extstate:module_wait_module event
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
validator operate: query data1.datanet.home. A IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
validator: nextmodule returned
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
val handle processing q with state VAL_INIT_STATE
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
validator classification positive
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
no signer, using data1.datanet.home. TYPE0 CLASS0
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
prime trust anchor
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
generate request . DNSKEY IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
mesh_run: validator module exit state is module_wait_subquery
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
validator[module 0] operate: extstate:module_state_initial eve
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
validator operate: query . DNSKEY IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
validator: pass to next module
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
mesh_run: validator module exit state is module_wait_module
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iterator[module 1] operate: extstate:module_state_initial even
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
process_request: new external request event
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iter_handle processing q with state INIT REQUEST STATE
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
resolving . DNSKEY IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
request has dependency depth of 0
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
priming . IN NS
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
mesh_run: iterator module exit state is module_wait_subquery
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iterator[module 1] operate: extstate:module_state_initial even
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
iterator operate: query . NS IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
iter_handle processing q with state QUERY TARGETS STATE
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
processQueryTargets: . NS IN
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] debug:
processQueryTargets: targetqueries 0, currentqueries 0 sentcou
Jul 24 20:45:31 pizza.yoderdev.com unbound[18236]: [18236:0] info:
DelegationPoint<.>: 13 names (2 missing), 24 addrs (0 result, 2
After this it looks like it's going to upstream root DNS servers, but
I'm not 100% clear what's going on here from the logs.
Here is my entire unbound.conf. I don't think nsd.conf is relevant
since that clearly is working.
server:
interface: 127.0.0.1
interface: 192.168.1.50
use-syslog: yes
username: "unbound"
directory: "/etc/unbound"
trust-anchor-file: trusted-key.key
access-control: 192.168.1.0/24 allow
#verbosity: 4
local-zone: "1.168.192.in-addr.arpa" nodefault
do-not-query-localhost: no
remote-control:
control-enable: yes
control-interface: 127.0.0.1
control-port: 8953
server-key-file: "/etc/unbound/unbound_server.key"
server-cert-file: "/etc/unbound/unbound_server.pem"
control-key-file: "/etc/unbound/unbound_control.key"
control-cert-file: "/etc/unbound/unbound_control.pem"
stub-zone:
name: "datanet.home"
stub-addr: 192.168.1.50@53530
stub-zone:
name: "1.168.192.in-addr.arpa"
stub-addr: 192.168.1.50@53530
Any pointers would be awesome. This is driving me nuts. Thanks!
