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://unbound.nlnetlabs.nl/pipermail/unbound-users/attachments/20110919/dbf3cd77/attachment-0001.html>