Maintained by: NLnet Labs

[Unbound-users] unbound has info, but does not answer it

Over Dexia
Mon Aug 19 15:47:32 CEST 2013


Hello list people,

I have set up a Maradns server on port 127.0.0.1, port 55.

I intended to put an unbound in front of it.

I have a handful of records configured. For this test, I try to resolve 
maradnstest.testdomain.de.

When I ask the local maradns on port 55, I get an answer:

---------------8<---------------8<---------------8<---------------
 > dig -p 55 maradnstest.testdomain.de @127.0.0.1

; <<>> DiG 9.8.4-rpz2+rl005.12-P1 <<>> -p 55 maradnstest.testdomain.de 
@127.0.0.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 35829
;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 2, ADDITIONAL: 0
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;maradnstest.testdomain.de.          IN      A

;; ANSWER SECTION:
maradnstest.testdomain.de.   86400   IN      A       10.125.99.99

;; AUTHORITY SECTION:
testdomain.de.               86400   IN      NS      ns1.testdomain.de.
testdomain.de.               86400   IN      NS      ns2.testdomain.de.

;; Query time: 0 msec
;; SERVER: 127.0.0.1#55(127.0.0.1)
;; WHEN: Mon Aug 19 15:28:35 2013
;; MSG SIZE  rcvd: 90
---------------8<---------------8<---------------8<---------------

10.125.99.99 is the answer I'm looking for.

Here's the excerpt of the unbound.conf which should make the link to the 
maradns:

         stub-zone:
                 name: testdomain.de
                 stub-addr: 127.0.0.1 at 55


However, when I'm asking the unbound on port 53 for a record, the 
request times out:

---------------8<---------------8<---------------8<---------------
# dig -p 53 maradnstest.testdomain.de @127.0.0.1

; <<>> DiG 9.8.4-rpz2+rl005.12-P1 <<>> -p 53 maradnstest.testdomain.de 
@127.0.0.1
;; global options: +cmd
;; connection timed out; no servers could be reached
---------------8<---------------8<---------------8<---------------

But the unbound server runs, is tied to all addresses and protocols and 
the debug shows it's doing a *lot* of work on my request, including 
requesting the maradns and getting an answer:

---------------8<---------------8<---------------8<---------------
...
Aug 19 14:41:01 unbound[7546:0] info: sending query: 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] debug: sending to target: 
<testdomain.de.> 127.0.0.1#55
Aug 19 14:41:01 unbound[7546:0] debug: dnssec status: not expected
Aug 19 14:41:01 unbound[7546:0] debug: EDNS lookup known=0 vs=0
Aug 19 14:41:01 unbound[7546:0] debug: serviced query UDP timeout=376 msec
Aug 19 14:41:01 unbound[7546:0] debug: inserted new pending reply id=c00d
Aug 19 14:41:01 unbound[7546:0] debug: opened UDP if=0 port=26181
Aug 19 14:41:01 unbound[7546:0] debug: comm point start listening 11
Aug 19 14:41:01 unbound[7546:0] debug: mesh_run: iterator module exit 
state is module_wait_reply
Aug 19 14:41:01 unbound[7546:0] info: mesh_run: end 1 recursion states 
(1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 
0 replies dropped, 0 states jostled out
Aug 19 14:41:01 unbound[7546:0] info: 0RDd mod1 rep 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] debug: cache memory msg=33040 
rrset=33040 infra=1542 val=33196
Aug 19 14:41:01 unbound[7546:0] debug: answer cb
Aug 19 14:41:01 unbound[7546:0] debug: Incoming reply id = c00d
Aug 19 14:41:01 unbound[7546:0] debug: Incoming reply addr = ip4 
127.0.0.1 port 55 (len 16)
Aug 19 14:41:01 unbound[7546:0] debug: lookup size is 1 entries
Aug 19 14:41:01 unbound[7546:0] debug: received udp reply.
Aug 19 14:41:01 unbound[7546:0] debug: udp message[90:0] 
C00D840000010001000200000B6D617261646E73746573740564657869610264650000010001C00C000100010001518000040A7D6363C01800020001000151800006036E7331C018C01800020001000151800006036E7332C018
Aug 19 14:41:01 unbound[7546:0] debug: outnet handle udp reply
Aug 19 14:41:01 unbound[7546:0] debug: serviced query: EDNS works for 
ip4 127.0.0.1 port 55 (len 16)
Aug 19 14:41:01 unbound[7546:0] debug: measured roundtrip at 0 msec
Aug 19 14:41:01 unbound[7546:0] debug: svcd callbacks start
Aug 19 14:41:01 unbound[7546:0] debug: worker svcd callback for qstate 
0xa247548
Aug 19 14:41:01 unbound[7546:0] debug: mesh_run: start
Aug 19 14:41:01 unbound[7546:0] debug: iterator[module 1] operate: 
extstate:module_wait_reply event:module_event_reply
Aug 19 14:41:01 unbound[7546:0] info: iterator operate: query 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] debug: process_response: new external 
response event
Aug 19 14:41:01 unbound[7546:0] info: scrub for testdomain.de. NS IN
Aug 19 14:41:01 unbound[7546:0] info: response for 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] info: reply from <testdomain.de.> 
127.0.0.1#55
Aug 19 14:41:01 unbound[7546:0] info: incoming scrubbed packet: ;; 
->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
;; flags: qr aa ; QUERY: 1, ANSWER: 1, AUTHORITY: 2, ADDITIONAL: 0
;; QUESTION SECTION:
;; maradnstest.testdomain.de.        IN      A

;; ANSWER SECTION:
maradnstest.testdomain.de.   86400   IN      A       10.125.99.99

;; AUTHORITY SECTION:
testdomain.de.       86400   IN      NS      ns1.testdomain.de.
testdomain.de.       86400   IN      NS      ns2.testdomain.de.

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; WHEN: Thu Jan  1 01:00:00 1970
;; MSG SIZE  rcvd: 90

Aug 19 14:41:01 unbound[7546:0] debug: iter_handle processing q with 
state QUERY RESPONSE STATE
Aug 19 14:41:01 unbound[7546:0] info: query response was ANSWER
Aug 19 14:41:01 unbound[7546:0] debug: iter_handle processing q with 
state FINISHED RESPONSE STATE
Aug 19 14:41:01 unbound[7546:0] info: finishing processing for 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] debug: mesh_run: iterator module exit 
state is module_finished
Aug 19 14:41:01 unbound[7546:0] debug: validator[module 0] operate: 
extstate:module_wait_module event:module_event_moddone
Aug 19 14:41:01 unbound[7546:0] info: validator operate: query 
maradnstest.testdomain.de. A IN
Aug 19 14:41:01 unbound[7546:0] debug: validator: nextmodule returned
Aug 19 14:41:01 unbound[7546:0] debug: val handle processing q with 
state VAL_INIT_STATE
Aug 19 14:41:01 unbound[7546:0] debug: validator classification positive
Aug 19 14:41:01 unbound[7546:0] info: no signer, using 
maradnstest.testdomain.de. TYPE0 CLASS0
Aug 19 14:41:01 unbound[7546:0] info: prime trust anchor
Aug 19 14:41:01 unbound[7546:0] info: generate request . DNSKEY IN
Aug 19 14:41:01 unbound[7546:0] debug: mesh_run: validator module exit 
state is module_wait_subquery
Aug 19 14:41:01 unbound[7546:0] debug: validator[module 0] operate: 
extstate:module_state_initial event:module_event_pass
...
---------------8<---------------8<---------------8<---------------

However, it does not use this information to pass it on to the client. 
Instead, it seems to recurse through all root servers. I can add the 
log, if that would be interesting. For now, I'll post the end of a 
minutes lasting working streak:

---------------8<---------------8<---------------8<---------------

Aug 19 15:36:09 unbound[8442:0] info: DelegationPoint<de.>: 6 names (0 
missing), 10 addrs (10 result, 0 avail) cacheNS
Aug 19 15:36:09 unbound[8442:0] info:   z.nic.de. * A
Aug 19 15:36:09 unbound[8442:0] info:   s.de.net. * A
Aug 19 15:36:09 unbound[8442:0] info:   n.de.net. * A AAAA
Aug 19 15:36:09 unbound[8442:0] info:   l.de.net. * A AAAA
Aug 19 15:36:09 unbound[8442:0] info:   f.nic.de. * A AAAA
Aug 19 15:36:09 unbound[8442:0] info:   a.nic.de. * A AAAA
Aug 19 15:36:09 unbound[8442:0] debug:    ip6 2001:678:2::53 port 53 
(len 28)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 194.0.0.53 port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    ip6 2a02:568:0:2::53 port 53 
(len 28)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 81.91.164.5 port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    ip6 2001:668:1f:11::105 port 
53 (len 28)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 77.67.63.105 port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    ip6 2001:67c:1011:1::53 port 
53 (len 28)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 194.146.107.6 port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 195.243.137.26 port 53 
(len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    ip4 194.246.96.1 port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 194.146.107.6 port 
53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=120000
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 194.246.96.1 port 
53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=48128
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 81.91.164.5 port 
53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=48128
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 194.0.0.53 port 53 
(len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=48128
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 77.67.63.105 port 
53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=48128
Aug 19 15:36:09 unbound[8442:0] debug: servselect ip4 195.243.137.26 
port 53 (len 16)
Aug 19 15:36:09 unbound[8442:0] debug:    rtt=48128
Aug 19 15:36:09 unbound[8442:0] debug: selrtt 48128
Aug 19 15:36:09 unbound[8442:0] info: sending query: de. DNSKEY IN
Aug 19 15:36:09 unbound[8442:0] debug: sending to target: <de.> 
77.67.63.105#53
Aug 19 15:36:09 unbound[8442:0] debug: dnssec status: expected
Aug 19 15:36:09 unbound[8442:0] debug: EDNS lookup known=0 vs=0
Aug 19 15:36:09 unbound[8442:0] debug: serviced query UDP timeout=48128 msec
Aug 19 15:36:09 unbound[8442:0] debug: inserted new pending reply id=c06c
Aug 19 15:36:09 unbound[8442:0] debug: opened UDP if=0 port=23691
Aug 19 15:36:09 unbound[8442:0] debug: comm point start listening 11
Aug 19 15:36:09 unbound[8442:0] debug: mesh_run: iterator module exit 
state is module_wait_reply
Aug 19 15:36:09 unbound[8442:0] info: mesh_run: end 2 recursion states 
(1 with reply, 0 detached), 3 waiting replies, 0 recursion replies sent, 
0 replies dropped, 0 states jostled out
Aug 19 15:36:09 unbound[8442:0] info: 0RDCD mod1  de. DNSKEY IN
Aug 19 15:36:09 unbound[8442:0] info: 1RDdc mod0 rep 
maradnstest.testdomain.de. A IN
Aug 19 15:36:09 unbound[8442:0] debug: cache memory msg=33932 
rrset=40359 infra=5224 val=34036
Aug 19 15:36:09 unbound[8442:0] debug: svcd callbacks end
Aug 19 15:36:09 unbound[8442:0] debug: close of port 51141
Aug 19 15:36:09 unbound[8442:0] debug: close fd 12

---------------8<---------------8<---------------8<---------------

What can I do to make unbound pass the name server answer to the 
requesting client?

Thanks in advance for any insight, jo