Unbound trying only one of three nameservers

And conveniently, that is the one server that seems to be unresponsive.

Trying to look up domain infoblox.com, with nameservers ns1, ns2 and
ns3.infoblox.com. It seems to work from outside sources like
zoneedit.com, 4.2.2.1, and dnswatch.info (they all probably skip the
dead NS).

ns3 is unresponsive, and also has a AAAA record. Unbound doesn't seem
to jump to any of the other ones, just keeps asking ns3 until it times
out. I'm very new to unbound, so please let me know what I should do
to debug this. This system (FreeBSD 7.0) doesn't have any IPv6 set
up.

Below is a "verbosity: 4" log.

$ dig @UNBOUND.SERVER infoblox.com a

; <<>> DiG 9.6.1-P1 <<>> @UNBOUND.SERVER infoblox.com a
; (2 servers found)
;; global options: +cmd
;; connection timed out; no servers could be reached

Snippet from the log file. Only able to grep for the domain as it's a
busy server:

[1300303603] unbound[95511:0] info: iterator operate: query
<ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: processQueryTargets:
<ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: DelegationPoint<infoblox.com.>: 3
names (0 missing), 5 addrs (3 result, 0 avail) parentNS
[1300303603] unbound[95511:0] info: ns3.infoblox.com. * A AAAA PSIDE_A
[1300303603] unbound[95511:0] info: ns2.infoblox.com. * A PSIDE_A
[1300303603] unbound[95511:0] info: ns1.infoblox.com. * A
[1300303603] unbound[95511:0] info: sending query: <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] debug: sending to target:
<infoblox.com.> 205.234.19.10#53
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 5RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 5RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 4RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
... few more hundred of these...

# egrep -v '^(#|.+#|$)' /usr/local/etc/unbound/unbound.conf
server:
        pidfile: /usr/local/etc/unbound/unbound.pid
        verbosity: 4
        interface: X.X.X.X
        do-ip6: no
        access-control: X.X.X.X/20 allow
        access-control: 10.0.0.0/8 allow
        access-control: 192.168.0.0/16 allow
        access-control: 172.16.0.0/12 allow
        logfile: "/var/log/unbound.log"
        hide-version: yes

        local-zone: "168.192.in-addr.arpa" nodefault
        local-zone: "16.172.in-addr.arpa" nodefault
        local-zone: "10.in-addr.arpa" nodefault
remote-control:
stub-zone:
        name: "16.172.in-addr.arpa."
        stub-host: auth1.ns.DOMAIN.net.
        stub-host: auth2.ns.DOMAIN.net.

stub-zone:
        name: "168.192.in-addr.arpa."
        stub-host: auth1.ns.DOMAIN.net.
        stub-host: auth2.ns.DOMAIN.net.

stub-zone:
        name: "10.in-addr.arpa."
        stub-host: auth1.ns.DOMAIN.net.
        stub-host: auth2.ns.DOMAIN.net.

stub-zone:
        name: "list.DOMAIN.net."
        stub-addr: X.X.X.X

# unbound -h
usage: unbound [options]
        start unbound daemon DNS resolver.
-h this help
-c file config file to read instead of /usr/local/etc/unbound/unbound.conf
        file format is described in unbound.conf(5).
-d do not fork into the background.
-v verbose (more times to increase verbosity)
Version 1.4.8
linked libs: mini-event internal (it uses select), ldns 1.6.8, OpenSSL
1.0.0d 8 Feb 2011
linked modules: validator iterator
configured for amd64-portbld-freebsd7.0 on Tue Mar 8 13:09:42 EST
2011 with options: '--with-ssl=/usr/local' '--with-ldns-builtin'
'--with-libevent=no' '--prefix=/usr/local' '--mandir=/usr/local/man'
'--infodir=/usr/local/info/' '--build=amd64-portbld-freebsd7.0'
BSD licensed, see LICENSE in source package for details.
Report bugs to unbound-bugs@nlnetlabs.nl

Hi Darek,

Could this have been a transient problem because it works now?

Also I see that the infoblox.com domain is DNSSEC signed now, perhaps
they recently migrated or some thing? If the ns1 and ns2 were somehow
'disqualified', by, say, not giving DNSSEC signatures, or advertising RA
(caching ability), unbound would prefer to get an answer from ns3.

It does not seem to be related to IPv6.

The log is ... short on usefulness, let me explain what you see (below).

And conveniently, that is the one server that seems to be unresponsive.

Trying to look up domain infoblox.com, with nameservers ns1, ns2 and
ns3.infoblox.com. It seems to work from outside sources like
zoneedit.com, 4.2.2.1, and dnswatch.info (they all probably skip the
dead NS).

ns3 is unresponsive, and also has a AAAA record. Unbound doesn't seem
to jump to any of the other ones, just keeps asking ns3 until it times
out. I'm very new to unbound, so please let me know what I should do
to debug this. This system (FreeBSD 7.0) doesn't have any IPv6 set
up.

Below is a "verbosity: 4" log.

$ dig @UNBOUND.SERVER infoblox.com a

; <<>> DiG 9.6.1-P1 <<>> @UNBOUND.SERVER infoblox.com a
; (2 servers found)
;; global options: +cmd
;; connection timed out; no servers could be reached

Snippet from the log file. Only able to grep for the domain as it's a
busy server:

Yes I understand that. Unbound-control lookup infoblox.com could tell
you about its nameservers.

[1300303603] unbound[95511:0] info: iterator operate: query
<ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: processQueryTargets:
<ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: DelegationPoint<infoblox.com.>: 3
names (0 missing), 5 addrs (3 result, 0 avail) parentNS
[1300303603] unbound[95511:0] info: ns3.infoblox.com. * A AAAA PSIDE_A
[1300303603] unbound[95511:0] info: ns2.infoblox.com. * A PSIDE_A
[1300303603] unbound[95511:0] info: ns1.infoblox.com. * A
[1300303603] unbound[95511:0] info: sending query: <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] debug: sending to target:
<infoblox.com.> 205.234.19.10#53
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 5RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 3RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 5RDdc mod1 rep <infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 4RDCD mod1 <ns3.infoblox.com. A IN>
[1300303603] unbound[95511:0] info: 6RDdc mod1 rep <infoblox.com. A IN>
... few more hundred of these...

The output is from the first second, see the same timestamp. The first
query is sent out. All the 'mod1' lines are just from lists showing
what is in the requestlist, and indicate it is waiting for an answer.

The first part 'operate query ...' there are the more interesting lines.
The sending query line is very indicative. If an answer comes in or it
times out, the query is operated again.

        do-ip6: no

So it is not IPv6 related, as you have it turned off.

If the server is very busy, the optimise page (
http://www.unbound.net/documentation/howto_optimise.html ) talks about
linking libevent and thus getting more performance.

Best regards,
   Wouter