Unbound has info, but does not answer it

Unbound
1

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@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

2

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

3

-----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).

This is very important info, thanks.

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.

Since I need the unbound to serve information (gathered from internal servers) even when the internet is unavailable, I probably have to disable DNSSEC.

This solved my problem. Thanks a lot for your help and best regards, jo

4

Hi Over,

unbound to serve information (gathered from internal servers) even
when the internet is unavailable, I probably have to disable
DNSSEC.

For this you should create lines for your localdomain(s):
domain-insecure: "local"

So that unbound does not have to go to the internet for dnssec for
your local domains, and then when internet is not available it does
not try to setup the chain of trust. It then uses DNSSEC for the
internet, but does not use DNSSEC for "local" names.

This solved my problem. Thanks a lot for your help and best
regards, jo

:slight_smile:

Best regards,
   Wouter

5

Fantastic. Thanks a lot! jo