Bug 786 - Unbound unstable resolving a domain
Unbound unstable resolving a domain
Status: ASSIGNED
Product: unbound
Classification: Unclassified
Component: server
1.5.9
x86_64 Linux
: P5 normal
Assigned To: unbound team
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2016-07-01 23:05 CEST by suporte
Modified: 2016-07-04 09:29 CEST (History)
2 users (show)

See Also:


Attachments
debug (567.35 KB, text/plain)
2016-07-02 02:45 CEST, suporte
Details

Note You need to log in before you can comment on or make changes to this bug.
Description suporte 2016-07-01 23:05:31 CEST
One of the domains that unbound is resolving is unstable:

Each couple of minutes I can't access the domain terra.com.br

I tried resolving using drill:

drill terra.com.br @localhost
;; ->>HEADER<<- opcode: QUERY, rcode: SERVFAIL, id: 54578
;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0 
;; QUESTION SECTION:
;; terra.com.br.	IN	A

;; ANSWER SECTION:

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; SERVER: 127.0.0.1
;; WHEN: Fri Jul  1 17:47:22 2016
;; MSG SIZE  rcvd: 30

look: rcode: SERVFAIL

unbound-host -vdD terra.com.br
[1467405989] libunbound[9259:0] notice: init module 0: validator
[1467405989] libunbound[9259:0] notice: init module 1: iterator
[1467405989] libunbound[9259:0] info: resolving terra.com.br. A IN
[1467405989] libunbound[9259:0] info: priming . IN NS
[1467405989] libunbound[9259:0] info: response for . NS IN
[1467405989] libunbound[9259:0] info: reply from <.> 192.33.4.12#53
[1467405989] libunbound[9259:0] info: query response was ANSWER
[1467405989] libunbound[9259:0] info: priming successful for . NS IN
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:500:2d::d port 53
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:500:9f::42 port 53
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:500:1::53 port 53
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:dc3::35 port 53
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:503:ba3e::2:30 port 53
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:500:9f::42 port 53
[1467405989] libunbound[9259:0] info: response for terra.com.br. A IN
[1467405989] libunbound[9259:0] info: reply from <.> 199.7.83.42#53
[1467405989] libunbound[9259:0] info: query response was REFERRAL
[1467405989] libunbound[9259:0] info: error sending query to auth server 2001:12ff::10 port 53
[1467405990] libunbound[9259:0] info: response for terra.com.br. A IN
[1467405990] libunbound[9259:0] info: reply from <br.> 200.189.41.10#53
[1467405990] libunbound[9259:0] info: query response was REFERRAL
[1467405990] libunbound[9259:0] info: error sending query to auth server 2001:12c0:0:2151:200:154:46:20 port 53
[1467405990] libunbound[9259:0] info: response for terra.com.br. A IN
[1467405990] libunbound[9259:0] info: reply from <terra.com.br.> 200.215.194.1#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
[1467405990] libunbound[9259:0] info: prime trust anchor
[1467405990] libunbound[9259:0] info: resolving . DNSKEY IN
[1467405990] libunbound[9259:0] info: error sending query to auth server 2001:dc3::35 port 53
[1467405990] libunbound[9259:0] info: response for . DNSKEY IN
[1467405990] libunbound[9259:0] info: reply from <.> 199.7.91.13#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
[1467405990] libunbound[9259:0] info: validate keys with anchor(DS): sec_status_secure
[1467405990] libunbound[9259:0] info: Successfully primed trust anchor . DNSKEY IN
[1467405990] libunbound[9259:0] info: validated DS br. DS IN
[1467405990] libunbound[9259:0] info: resolving br. DNSKEY IN
[1467405990] libunbound[9259:0] info: response for br. DNSKEY IN
[1467405990] libunbound[9259:0] info: reply from <br.> 200.192.233.10#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
[1467405990] libunbound[9259:0] info: validated DNSKEY br. DNSKEY IN
[1467405990] libunbound[9259:0] info: resolving com.br. DS IN
[1467405990] libunbound[9259:0] info: response for com.br. DS IN
[1467405990] libunbound[9259:0] info: reply from <br.> 200.219.154.10#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
[1467405990] libunbound[9259:0] info: validated DS com.br. DS IN
[1467405990] libunbound[9259:0] info: resolving com.br. DNSKEY IN
[1467405990] libunbound[9259:0] info: response for com.br. DNSKEY IN
[1467405990] libunbound[9259:0] info: reply from <br.> 200.192.233.10#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
[1467405990] libunbound[9259:0] info: validated DNSKEY com.br. DNSKEY IN
[1467405990] libunbound[9259:0] info: NSEC3s for the referral proved no DS.
[1467405990] libunbound[9259:0] info: Verified that unsigned response is INSECURE
terra.com.br has address 208.84.244.116 (insecure)
[1467405990] libunbound[9259:0] info: resolving terra.com.br. AAAA IN
[1467405990] libunbound[9259:0] info: response for terra.com.br. AAAA IN
[1467405990] libunbound[9259:0] info: reply from <terra.com.br.> 200.215.193.1#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
terra.com.br has IPv6 address 2604:600:0:aaaa:208:84:244:116 (insecure)
[1467405990] libunbound[9259:0] info: resolving terra.com.br. MX IN
[1467405990] libunbound[9259:0] info: error sending query to auth server 2001:12c0:0:2151:200:154:46:21 port 53
[1467405990] libunbound[9259:0] info: response for terra.com.br. MX IN
[1467405990] libunbound[9259:0] info: reply from <terra.com.br.> 200.215.194.1#53
[1467405990] libunbound[9259:0] info: query response was ANSWER
terra.com.br mail is handled by 10 vip-us-br-mx.terra.com. (insecure)


After a couple of minutes I can resolve it normally:

drill terra.com.br @127.0.0.1
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 59696
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 4, ADDITIONAL: 4 
;; QUESTION SECTION:
;; terra.com.br.	IN	A

;; ANSWER SECTION:
terra.com.br.	720	IN	A	208.84.244.116

;; AUTHORITY SECTION:
terra.com.br.	86400	IN	NS	d.dns.terra.com.br.
terra.com.br.	86400	IN	NS	a.dns.terra.com.
terra.com.br.	86400	IN	NS	b.dns.terra.com.br.
terra.com.br.	86400	IN	NS	c.dns.terra.com.

;; ADDITIONAL SECTION:
b.dns.terra.com.br.	172795	IN	A	200.215.193.1
b.dns.terra.com.br.	715	IN	AAAA	2001:12c0:0:2151:200:154:46:20
d.dns.terra.com.br.	172795	IN	A	200.215.194.1
d.dns.terra.com.br.	715	IN	AAAA	2001:12c0:0:2151:200:154:46:21

;; Query time: 7 msec
;; SERVER: 127.0.0.1
;; WHEN: Fri Jul  1 17:48:49 2016
;; MSG SIZE  rcvd: 215




cat /etc/unbound/unbound.conf
server:
    use-syslog: yes
    username: "unbound"
    directory: "/etc/unbound"
    interface: 127.0.0.1
    interface: x.x.x.x
    trust-anchor-file: trusted-key.key
    access-control: x.x.x.x/20 allow
    access-control: y.y.y.y/20 allow
    access-control: z.z.z.z/22 allow
    root-hints: "/etc/unbound/root.hints"
    #num-threads: 4
    extended-statistics: yes
    val-log-level: 2
  
remote-control:
    # Enable remote control with unbound-control(8) here.
    # set up the keys and certificates with unbound-control-setup.
    control-enable: yes
   
    # what interfaces are listened to for remote control.
    # give 0.0.0.0 and ::0 to listen to all interfaces.
    control-interface: 127.0.0.1
   
    # port number for remote control operations.
    control-port: 8953
   
    # unbound server key file.
    server-key-file: "/etc/unbound/unbound_server.key"
   
    # unbound server certificate file.
    server-cert-file: "/etc/unbound/unbound_server.pem"
   
    # unbound-control key file.
    control-key-file: "/etc/unbound/unbound_control.key"
   
    # unbound-control certificate file.
    control-cert-file: "/etc/unbound/unbound_control.pem"
Comment 1 suporte 2016-07-02 02:45:04 CEST
Created attachment 332 [details]
debug

Now I think that I have a better log!


The resolver stay in loop. I've canceled in line:

[1467418844] libunbound[13863:0] debug: close fd 12

I started again and after few other tries the resolver got success.


log attached
Comment 2 Wouter Wijngaards 2016-07-04 09:29:01 CEST
Hi,

The domain keeps giving timeouts.  It seems intermittently offline and not responding (to any IP address, lots of queries in sequence).

You have ipv6 enabled, and unbound starts exploring ip6 connectivity to the domain, which it says it has, but you haven't, and this wastes time.  do-ip6: no could solve this in unbound.conf.  Or you could enable IPv6, perhaps their IPv6 connectivity is better.   If you do do-ip6: no in unbound.conf unbound can spend more time sending probes to the affected domain.  Or enable IPv6 for the same effect and also unbound has more choice in servers that hopefully work.

The domain gives timeouts and has a short (720 second, a couple minutes) TTL.   This causes the unstability you mention.  Enabling prefetch may somewhat alleviate this, if the domain is prefetched such short periods of disconnection may become unnoticed, as unbound simply prefetches it again a couple seconds later.

The domain owner is urged, by the way, in several BCP statements to have the servers in independent locations, i.e. that don't go offline at the same time.

Best regards, Wouter