[Unbound-users] unbound has info, but does not answer it
Over Dexia
over at dexia.de
Mon Aug 19 13:47:32 UTC 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
More information about the Unbound-users
mailing list