Problems with dipmap.com

Attila_Nagy · September 19, 2011, 11:03am

Hi,

There is a problem with resolving names from dipmap.com with unbound.
Currently, the root NSs give back three nameservers, from which only one works (at least from our network).
And that one has a bad NS RR:
$ dig ns dipmap.com @ns.dipmap.com.

; <<>> DiG 9.6.-ESV-R4-P1 <<>> ns dipmap.com @ns.dipmap.com.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 25982
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;dipmap.com. IN NS

;; ANSWER SECTION:
dipmap.com. 60 IN NS sql2005.

It seems that unbound stores that nameserver and wants to query it, so either a time out or a SERVFAIL happens to the client.

I thought that a recursive DNS server shouldn’t cache NS records from the zone’s authoritative name server, it should only trust in the upper servers.
ISC BIND doesn’t have this behaviour -it seems-, so it can resolve names from this domain.

Wouter · September 19, 2011, 12:08pm

Hi Attila,

Hi,

There is a problem with resolving names from dipmap.com with unbound.
Currently, the root NSs give back three nameservers, from which only one
works (at least from our network).
And that one has a bad NS RR:
$ dig ns dipmap.com @ns.dipmap.com.

; <<>> DiG 9.6.-ESV-R4-P1 <<>> ns dipmap.com @ns.dipmap.com.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 25982
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;dipmap.com. IN NS

;; ANSWER SECTION:
dipmap.com. 60 IN NS sql2005.

It seems that unbound stores that nameserver and wants to query it, so
either a time out or a SERVFAIL happens to the client.

Yes it wants to query it, but in my test it quickly finds out that the
bad-name does not exist. Then it tries the last resort: it falls back
to the parent nameserver NSset. And this works. So it works fine for me?

I thought that a recursive DNS server shouldn't cache NS records from
the zone's authoritative name server, it should only trust in the upper
servers.

No, the child's server is the most authoritative for its NS record. The
upper servers only give hints to reach the child. But this zone is
misconfigured, yeah.

ISC BIND doesn't have this behaviour -it seems-, so it can resolve names
from this domain.

Well, so should we really. Since it works for me, but not for you, can
you tell me what happens when it does not want to work: set verbosity to
4 and do a probe and look at the logs. It should try the last resort.

This was added in 1.4.5 so if you are running older unbound, that would
explain.

Best regards,
Wouter

Attila_Nagy · September 19, 2011, 1:27pm

Hi,

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

Hi Attila,

Hi,

There is a problem with resolving names from dipmap.com with unbound.
Currently, the root NSs give back three nameservers, from which only one
works (at least from our network).
And that one has a bad NS RR:
$ dig ns dipmap.com @ns.dipmap.com.

; <<>> DiG 9.6.-ESV-R4-P1 <<>> ns dipmap.com @ns.dipmap.com.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 25982
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;dipmap.com.                    IN      NS

;; ANSWER SECTION:
dipmap.com.             60      IN      NS      sql2005.

It seems that unbound stores that nameserver and wants to query it, so
either a time out or a SERVFAIL happens to the client.

Yes it wants to query it, but in my test it quickly finds out that the
bad-name does not exist.  Then it tries the last resort: it falls back
to the parent nameserver NSset.  And this works.  So it works fine for me?

Well, it works for me too for a while. Then it starts to not (SERVFAIL or timed out request, other queries get answered correctly). I do the testing with tirparkolo.dipmap.com.

I thought that a recursive DNS server shouldn't cache NS records from
the zone's authoritative name server, it should only trust in the upper
servers.

No, the child's server is the most authoritative for its NS record.  The
upper servers only give hints to reach the child.  But this zone is
misconfigured, yeah.

Hmm, I thought the opposite is true, which makes more sense to me. I’ve seen a lot of cases where only one NS was working out of the X and that NS had totally different other nameservers than in the “internet view” (from the root NSes). Of course when the only working NS has disappeared, nobody could resolve the domain, no matter the domain’s administrator set the correct nameservers (at least he thought he did) which were accessible.
Nobody queried them, because the administrator forgot to make the changes in the internet infrastrucutre (above his server).

Does unbound re-checks the hints (the upper nameservers) for a given zone when the NS TTL expires?

ISC BIND doesn't have this behaviour -it seems-, so it can resolve names
from this domain.

Well, so should we really.  Since it works for me, but not for you, can
you tell me what happens when it does not want to work: set verbosity to
4 and do a probe and look at the logs.  It should try the last resort.

This was added in 1.4.5 so if you are running older unbound, that would
explain.

No, it’s a nearly up to date trunk (I can give exact subversion revision).
Here’s the verbose log:
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: pass to next module
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_wait_module
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_wait_module
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: process_request: new external request event
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: request has dependency depth of 0
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cache delegation returns delegpt
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 2): tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 3): tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 3 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: Bad choices, trying to get more choice
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: no current targets -- waiting for 4 targets to resolve.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_wait_subquery
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: request has dependency depth of 1
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cache delegation returns delegpt
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 2): ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 3): ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: Bad choices, trying to get more choice
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: no current targets -- waiting for 3 targets to resolve.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_wait_subquery
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: request has dependency depth of 1
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cache delegation returns delegpt
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 2): ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 3): ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: new target ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: Bad choices, trying to get more choice
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: no current targets -- waiting for 1 targets to resolve.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_wait_subquery
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: request has dependency depth of 1
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cache delegation returns delegpt
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 2): ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 3): ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (3 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side NS in cache dipmap.com. NS IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: try parent-side glue from cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 3 addrs (2 result, 1 avail) parentNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4 202.133.227.43 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: out of query targets -- returning SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: store error response in message cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: return error response SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: nextmodule returned
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: not validating response due to CD bit
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: pythonmod: clear, id: 1, pq:8027F14B0
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 2 addrs (2 result, 0 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. *
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side NS in cache dipmap.com. NS IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: try parent-side glue from cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 3 addrs (2 result, 1 avail) parentNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4 202.133.227.43 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: out of query targets -- returning SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: store error response in message cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: return error response SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: nextmodule returned
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: not validating response due to CD bit
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: pythonmod: clear, id: 1, pq:8027F14B0
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 1, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 2 addrs (2 result, 0 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: Bad choices, trying to get more choice
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: no current targets -- waiting for 1 targets to resolve.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_wait_subquery
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 2, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 2 addrs (2 result, 0 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 3 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: Bad choices, trying to get more choice
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: no current targets -- waiting for 2 targets to resolve.
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_wait_subquery
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: request has dependency depth of 1
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cache delegation returns delegpt
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (2 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 2): ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Sep 19 15:16:40 cns01d unbound: [61501:2] info: resolving (init part 3): ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (2 missing), 2 addrs (0 result, 2 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: skipping target due to dependency cycle (harden-glue: no may fix some of the cycles) ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side NS in cache dipmap.com. NS IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: try parent-side glue from cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 3 addrs (2 result, 1 avail) parentNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4 202.133.227.43 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: out of query targets -- returning SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: store error response in message cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: return error response SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: nextmodule returned
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: not validating response due to CD bit
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: pythonmod: clear, id: 1, pq:8027F14B0
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 2 addrs (2 result, 0 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side NS in cache dipmap.com. NS IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: try parent-side glue from cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 3 addrs (2 result, 1 avail) parentNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4 202.133.227.43 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 2 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: out of query targets -- returning SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: store error response in message cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: return error response SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_moddone
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: nextmodule returned
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: not validating response due to CD bit
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: pythonmod: clear, id: 1, pq:8027F14B0
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Sep 19 15:16:40 cns01d unbound: [61501:2] info: iterator operate: query tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 2 addrs (2 result, 0 avail) cacheNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * A AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 3 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side NS in cache dipmap.com. NS IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: try parent-side glue from cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: iter_handle processing q with state QUERY TARGETS STATE
Sep 19 15:16:40 cns01d unbound: [61501:2] info: processQueryTargets: tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: processQueryTargets: targetqueries 0, currentqueries 0
Sep 19 15:16:40 cns01d unbound: [61501:2] info: DelegationPoint<dipmap.com.>: 3 names (0 missing), 3 addrs (2 result, 1 avail) parentNS
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns2.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns1.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] info: ns.dipmap.com. * A AAAA PSIDE_A PSIDE_AAAA
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4 202.133.227.43 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: attempt to get extra 3 targets
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.11 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: servselect ip4 202.133.254.12 port 53 (len 16)
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: rtt=120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: selrtt 120000
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: chase to blacklisted lame server
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: No more query targets, attempting last resort
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found in cache ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns2.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns1.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] info: found parent-side ns.dipmap.com. AAAA IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: out of query targets -- returning SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: store error response in message cache
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: return error response SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: iterator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: python module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query tirparkolo.dipmap.com. A IN
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: validator: nextmodule returned
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: cannot validate non-answer, rcode SERVFAIL
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: mesh_run: validator module exit state is module_finished
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: query took 0.000000 sec
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: pythonmod: clear, id: 1, pq:8027F1410

Only ns.dipmap.com is accessible, the others don’t answer.

Wouter · September 19, 2011, 1:34pm

No, it's a nearly up to date trunk (I can give exact subversion revision).
Here's the verbose log:
Sep 19 15:16:40 cns01d unbound: [61501:2] info: validator operate: query
tirparkolo.dipmap.com. A IN

..

Only ns.dipmap.com is accessible, the others don't answer.

So it says:
Sep 19 15:16:40 cns01d unbound: [61501:2] debug: ADDR_LAME ip4
202.133.227.43 port 53 (len 16)

So the only working one, ns.dipmap is LAME. That flag means that it
seems to not serve the zone at all. It serves upwards referral (like
BIND does) for the zones that it does not have. This was seen and
cached for dipmap.com for the .43 IP address. The host cache times out
in 15 minutes.

Best regards,
Wouter

Attila_Nagy · September 19, 2011, 1:43pm

Indeed, it looks very lame. My only problem is that the user says “it’s working elsewhere”.
For example google&opendns serves it right.

Wouter · September 19, 2011, 1:51pm

I do not understand how they continue to query LAME servers. You are
not supposed to do so. BIND would not do so too. Is it that it only
gives lame answers to some queries or some queriers? If it would not
give Lame answers, then it would work with unbound (and the parent-child
disagreement would not be an issue).

Best regards, Wouter

Hauke_Lampe · September 19, 2011, 3:41pm

I do not understand how they continue to query LAME servers.

Doesn't look lame to me. It answers queries for tirparkolo.dipmap.com as
well as for ns/ns1/ns2.dipmap.com. Only the NS record is wrong.

My Unbound resolver (current svn) keeps returing the correct answer.

If it would not
give Lame answers, then it would work with unbound (and the parent-child
disagreement would not be an issue).

Shouldn't it fail with "harden-referral-path" set? Or is it enough if
the child servers sends answers for the nameserver names from the parent
zone even if the NS records differ?

Here's a query trace from unbound-host w/ harden-referral-path:
http://pastebin.com/VU3tuN3J

Hauke.

Wouter · September 20, 2011, 7:46am

Hi Hauke, Robert,

I do not understand how they continue to query LAME servers.

Doesn't look lame to me. It answers queries for tirparkolo.dipmap.com as
well as for ns/ns1/ns2.dipmap.com. Only the NS record is wrong.

My Unbound resolver (current svn) keeps returing the correct answer.

There is a bug, which I fixed (thank Amanda from Secure64), it has a
wrong classification internally. What is also wrong with the
dir.slb.com setup (how many things can you break at the same time?) is
that the slb.com DNS servers are stealth serving the dir.slb.com zone as
well. Their AA answer is the final answer for BIND, but unbound
classified it wrong and wanted to as dir.slb.com DNS servers for the
answer ... but those do not answer. Fixed in svn trunk.

If it would not
give Lame answers, then it would work with unbound (and the parent-child
disagreement would not be an issue).

Shouldn't it fail with "harden-referral-path" set? Or is it enough if
the child servers sends answers for the nameserver names from the parent
zone even if the NS records differ?

Here's a query trace from unbound-host w/ harden-referral-path:
http://pastebin.com/VU3tuN3J

No, harden referral path is OK if the answer does not arrive for the NS
set. It is lenient for this sort of brokenness.

Best regards,
Wouter