Unbound 1.13.1 - Cannot resolve host

Robert_Blayzor · June 25, 2021, 4:09pm

I have a very strange issue with a domain that works on none of my unbound caching servers. Looking this domain up directly using bind dig & drill trace seems to complete. Also if I asked the authoritative answers all is good. If i ask Google or Cloudflare public servers, things are fine.

Domain: bborganizing.com

When running through unbound-host debug I get:

[1624636494] libunbound[49228:0] debug: request has exceeded the maximum number of nxdomain nameserver lookups with 6
[1624636494] libunbound[49228:0] debug: return error response SERVFAIL
[1624636494] libunbound[49228:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1624636494] libunbound[49228:0] info: validator operate: query bborganizing.com. A IN
Host bborganizing.com not found: 2(SERVFAIL). (error)

Which is due to the fact it's name server do not seem to resolve. The name servers listed are ns6517.hostgator.com and ns6518.hostgator.com. If I asked those servers directly, things work, but if I look them up through our unbound servers, I get a serve fail.

Keep in mind, this works through bind name servers and others, just not unbound... stumped...

unbound-host -t a -v -dd ns6517.hostgator.com

[1624637282] libunbound[49252:0] debug: switching log to stderr
[1624637282] libunbound[49252:0] debug: module config: "validator iterator"
[1624637282] libunbound[49252:0] notice: init module 0: validator
[1624637282] libunbound[49252:0] notice: init module 1: iterator
[1624637282] libunbound[49252:0] debug: target fetch policy for level 0 is 0
[1624637282] libunbound[49252:0] debug: target fetch policy for level 1 is 0
[1624637282] libunbound[49252:0] debug: target fetch policy for level 2 is 0
[1624637282] libunbound[49252:0] debug: target fetch policy for level 3 is 0
[1624637282] libunbound[49252:0] debug: target fetch policy for level 4 is 0
[1624637282] libunbound[49252:0] debug: Reading root hints from named.cache
[1624637282] libunbound[49252:0] info: DelegationPoint<.>: 13 names (0 missing), 26 addrs (0 result, 26 avail) parentNS
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
[1624637282] libunbound[49252:0] info: validator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: resolving ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: priming . IN NS
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: iterator operate: query . NS IN
[1624637282] libunbound[49252:0] info: processQueryTargets: . NS IN
[1624637282] libunbound[49252:0] info: sending query: . NS IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 192.58.128.30#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query . NS IN
[1624637282] libunbound[49252:0] info: response for . NS IN
[1624637282] libunbound[49252:0] info: reply from <.> 192.58.128.30#53
[1624637282] libunbound[49252:0] info: query response was ANSWER
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query . NS IN
[1624637282] libunbound[49252:0] info: priming successful for . NS IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1624637282] libunbound[49252:0] info: iterator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: processQueryTargets: ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: removing 2 labels
[1624637282] libunbound[49252:0] info: sending query: com. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 202.12.27.33#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: response for ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: reply from <.> 202.12.27.33#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: removing 1 labels
[1624637282] libunbound[49252:0] info: sending query: hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <com.> 2001:500:856e::30#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: response for ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: reply from <com.> 2001:500:856e::30#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: new target dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: new target dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: resolving dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: removing 3 labels
[1624637282] libunbound[49252:0] info: sending query: net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 198.41.0.4#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: resolving dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: removing 3 labels
[1624637282] libunbound[49252:0] info: sending query: net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 192.33.4.12#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: reply from <.> 192.33.4.12#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: removing 2 labels
[1624637282] libunbound[49252:0] info: sending query: nsone.net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <net.> 2001:501:b1f9::30#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: reply from <.> 198.41.0.4#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: removing 2 labels
[1624637282] libunbound[49252:0] info: sending query: nsone.net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <net.> 192.54.112.30#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: reply from <net.> 2001:501:b1f9::30#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: removing 1 labels
[1624637282] libunbound[49252:0] info: sending query: p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <nsone.net.> 2620:4d:4000:6259:7:1:0:3#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: reply from <nsone.net.> 2620:4d:4000:6259:7:1:0:3#53
[1624637282] libunbound[49252:0] info: query response was nodata ANSWER
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: sending query: dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <nsone.net.> 198.51.44.65#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] info: reply from <nsone.net.> 198.51.44.65#53
[1624637282] libunbound[49252:0] info: query response was ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query dns2.p06.nsone.net. A IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
[1624637282] libunbound[49252:0] info: iterator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: processQueryTargets: ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: sending query: ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <hostgator.com.> 198.51.45.6#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: sanitize: removing public name with private address <ns6517.hostgator.com.> 192.254.235.225#53
[1624637282] libunbound[49252:0] info: response for ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: reply from <hostgator.com.> 198.51.45.6#53
[1624637282] libunbound[49252:0] info: query response was nodata ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: prime trust anchor
[1624637282] libunbound[49252:0] info: generate keytag query _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: validator operate: query . DNSKEY IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: resolving . DNSKEY IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): . DNSKEY IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): . DNSKEY IN
[1624637282] libunbound[49252:0] info: processQueryTargets: . DNSKEY IN
[1624637282] libunbound[49252:0] info: sending query: . DNSKEY IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 192.203.230.10#53
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: validator operate: query _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: resolving _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: processQueryTargets: _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: sending query: _ta-4f66. A IN
[1624637282] libunbound[49252:0] debug: sending to target: <.> 2001:500:2d::d#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query . DNSKEY IN
[1624637282] libunbound[49252:0] info: response for . DNSKEY IN
[1624637282] libunbound[49252:0] info: reply from <.> 192.203.230.10#53
[1624637282] libunbound[49252:0] info: query response was ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for . DNSKEY IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query . DNSKEY IN
[1624637282] libunbound[49252:0] info: validate keys with anchor(DS): sec_status_secure
[1624637282] libunbound[49252:0] info: Successfully primed trust anchor . DNSKEY IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
[1624637282] libunbound[49252:0] info: validator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: validated DS com. DS IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: validator operate: query com. DNSKEY IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1624637282] libunbound[49252:0] info: resolving com. DNSKEY IN
[1624637282] libunbound[49252:0] info: resolving (init part 2): com. DNSKEY IN
[1624637282] libunbound[49252:0] info: resolving (init part 3): com. DNSKEY IN
[1624637282] libunbound[49252:0] info: processQueryTargets: com. DNSKEY IN
[1624637282] libunbound[49252:0] info: sending query: com. DNSKEY IN
[1624637282] libunbound[49252:0] debug: sending to target: <com.> 192.48.79.30#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: response for _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] info: reply from <.> 2001:500:2d::d#53
[1624637282] libunbound[49252:0] info: query response was NXDOMAIN ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query _ta-4f66. NULL IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: reply from <net.> 192.54.112.30#53
[1624637282] libunbound[49252:0] info: query response was REFERRAL
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: removing 1 labels
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: processQueryTargets: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: sending query: dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: sending to target: <nsone.net.> 198.51.44.1#53
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: response for dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] info: reply from <nsone.net.> 198.51.44.1#53
[1624637282] libunbound[49252:0] info: query response was ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query dns2.p06.nsone.net. AAAA IN
[1624637282] libunbound[49252:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1624637282] libunbound[49252:0] info: iterator operate: query com. DNSKEY IN
[1624637282] libunbound[49252:0] info: response for com. DNSKEY IN
[1624637282] libunbound[49252:0] info: reply from <com.> 192.48.79.30#53
[1624637282] libunbound[49252:0] info: query response was ANSWER
[1624637282] libunbound[49252:0] info: finishing processing for com. DNSKEY IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1624637282] libunbound[49252:0] info: validator operate: query com. DNSKEY IN
[1624637282] libunbound[49252:0] info: validated DNSKEY com. DNSKEY IN
[1624637282] libunbound[49252:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
[1624637282] libunbound[49252:0] info: validator operate: query ns6517.hostgator.com. A IN
[1624637282] libunbound[49252:0] info: NSEC3s for the referral proved no DS.
[1624637282] libunbound[49252:0] info: Verified that unsigned response is INSECURE
ns6517.hostgator.com has no address (insecure)

Fong1 · June 25, 2021, 5:17pm

No suggestions yet... But writing you directly because I'm wondering if I can query your unbound server since we're in your house and monkey a bit?

FONG

Fong1 · June 25, 2021, 5:40pm

Sorry folks I guess I didn't write Robert directly... Carry on...

Fong1 · June 25, 2021, 7:46pm

So I have confirmed I am getting SERVFAIL for that domain when querying your unbound server. Was able to recreate success for dig +trace and queries off of outside caching nameservers.

But trying to figure out how dns2.p06.nsone.net is coming into play in the logs. Otherwise not seeing anything jumping out at me that looks real wrong.

What happens after you run?: unbound-control flush_zone bborganizing.com

Even if it resolves after that, from what you've described, I guess you'd have to keep an eye on it. Wondering if the zone is just getting corrupted somehow?

Robert_Blayzor · June 28, 2021, 1:55pm

I actually finally tracked this down. It had to do with some old options left in the FreeBSD port distro.

The old distro had "private-address: 192.254.0.0/16" which should not be there and was probably supposed to be "169.254.0.0/16".

Fong1 · June 29, 2021, 8:17pm

What FreeBSD version had this snafu pray tell?

Joe_Abley · June 29, 2021, 9:43pm

FreeBSD ports are not directly tied to FreeBSD releases.

Jaap maintains the unbound port. The full commit history is public, so it’s at least possible to track down precisely what commits introduced and removed the typo, even if it’s possibly not fun work to do.

https://www.freshports.org/dns/unbound/

Jaap · June 30, 2021, 7:19am

Joe Abley via Unbound-users writes:

> FreeBSD ports are not directly tied to FreeBSD releases.
>
> Jaap maintains the unbound port. The full commit history is public, so
> it's at least possible to track down precisely what commits introduced
> and removed the typo, even if it's possibly not fun work to do.

For ports I hardly ever change the contents release of the "upstreams"
so version numbers follow this case, the ones for unbound. I just
add the necessary scaffolding to make it a FreeBSD port. If the
change is documented, it will be in the Change Log for unbound (currently
<https://www.nlnetlabs.nl/projects/unbound/download/#unbound-1-13-1>\).
And indeed, it seems mentioned for the release of unbound 1.4.7 (November 2010).

jaap