Maintained by: NLnet Labs

unbound fetches DNS record from nsd but does not return it to client

Micah Yoder
Sat Aug 1 03:34:09 CEST 2015


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 at 53530
     stub-zone:
       name: "1.168.192.in-addr.arpa"
       stub-addr: 192.168.1.50 at 53530


Any pointers would be awesome. This is driving me nuts.  Thanks!