Maintained by: NLnet Labs

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

W.C.A. Wijngaards
Tue Aug 20 14:20:09 CEST 2013


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Over,

So the replies from maradns are fine, but then you have DNSSEC
validation enabled.  But DNSSEC replies do not make it from the
internet to you.

This bit:
> 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

So, queries for the root DNSKEY, .de DNSKEY all time out.  Probably,
you have a firewall that blocks DNS traffic bigger then 512.  Fix the
firewall or router.

Or, you somehow drop all traffic with EDNS0 in it.  The firewall
deep-inspects and drops DNS traffic with EDNS0 extensions (needed for
DNSSEC).

Another option is to disable dnssec validation.  But it is better to
fix your network firewalls, routers or other filtering, that drops
DNSSEC answers (such as the de DNSKEY).

Yet another option is to configure unbound to advertise an EDNS size
of 512.

Best regards,
   Wouter


On 08/19/2013 03:47 PM, Over Dexia wrote:
> 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 
> _______________________________________________ Unbound-users
> mailing list Unbound-users at unbound.net 
> http://unbound.nlnetlabs.nl/mailman/listinfo/unbound-users

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.14 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBAgAGBQJSE171AAoJEJ9vHC1+BF+NDa4QAKOeei8SJEO7pWp6sE6/CkaB
WZa5HzTVgGjoIPVok2VyIobIfXTtgJMuqNFse9qOzS2vrjH2wzyMoxLY0Bxq2ru0
gtJkP9mu2ljRQv/cJ7zAHe7TjyURAq2wAGdfe7o/aLP0ynErpbafqnt910VgK16m
LCjMhJ8HKoVLmL2/Nq8xM5tQd6PxBGE+1qwwD3naN3SyXnyIONDjc/6Jjskv1rwl
vr4qSvXhZ7qCcILKx23fd4lnA0CxzEIItWt3+1TZ12zoS1FOFNJhQSMXvGedpxsw
wROJYCmaf0GhXxC88SaPfB8Gjn3V9KZNVvd2qR3DVJpoBFWlM37T8rI0ExLo+byn
XG4ERlNjYtASNq3Bpl3SbtSw49I3pBMxh4aNhUX9USauasMHmg8igi3QQF+R2Bl6
hklzgL7aELmJFrCkhxbj3QfF9g33k7femfz2CYfROZbaL6rvxd8gOwX5tly8nBzR
YvkRTBJYp00FsHlDL4P6rq7m+WKpXD8wal02wTpArAUoKoruGfDoRvGZi2+IKJGK
80N2VQw1VGKnIWWoBOeGM+TgqRjixP3EvJPAe7BkWHFvxeyduqHSe9rMvwJswTQP
fCB1rvXzcQCP1lcKKHpVkBZB768xBIR0STLG0XLf4qLQz+mt54ZhLOu6XV+zrPAY
t/d0/3Gi9PZ29izXmtKf
=9iP8
-----END PGP SIGNATURE-----