[Unbound-users] Problems with dipmap.com

Attila Nagy bra at fsn.hu
Mon Sep 19 13:27:33 UTC 2011 

Hi,

On 09/19/11 14:08, W.C.A. Wijngaards wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> Hi Attila,
>
> On 09/19/2011 01:03 PM, Attila Nagy wrote:
>> 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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20110919/dbf3cd77/attachment.htm>

More information about the Unbound-users mailing list