[Unbound-users] queries to root servers not getting answered.

Mariano Absatz - gmail el.baby at gmail.com
Thu Aug 16 15:27:59 UTC 2012 

Hi,

I just compiled and installed lnsd 1.6.13 and unbound 1.4.18 on a debian
lenny VM.

Since I was getting temporary failures, I raised the log verbosity to 3 and
the log (which I add at the end of the message) seems to indicate that
queries to the root name server are either not being sent or not being
answered...

I kinda manually replicated the behavior of the resolver (using dbndns'
dnsq command) in the same machine and got instant responses in every case
(copied below the log).

Maybe someone with experience with unbound (and its logging) could help me
about where to look?

Any help would be greatly appreciated.

-- 
Mariano Absatz - El Baby
www.clueless.com.ar

################################### LOG FILE
###################################
[1345129608] unbound[19900:0] debug: module config: "validator iterator"
[1345129608] unbound[19900:0] notice: init module 0: validator
[1345129608] unbound[19900:0] notice: init module 1: iterator
[1345129608] unbound[19900:0] debug: target fetch policy for level 0 is 3
[1345129608] unbound[19900:0] debug: target fetch policy for level 1 is 2
[1345129608] unbound[19900:0] debug: target fetch policy for level 2 is 1
[1345129608] unbound[19900:0] debug: target fetch policy for level 3 is 0
[1345129608] unbound[19900:0] debug: target fetch policy for level 4 is 0
[1345129608] unbound[19900:0] debug: Reading root hints from
/etc/root-name-servers
[1345129608] unbound[19900:0] info: DelegationPoint<.>: 13 names (4
missing), 22 addrs (0 result, 22 avail) parentNS
[1345129608] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1304 val=33196
[1345129608] unbound[19900:0] info: start of service (unbound 1.4.18).

*######## Recursive query sent:*
*######## dnsqr a www.hp.com*

[1345129616] unbound[19900:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_new
[1345129616] unbound[19900:0] info: validator operate: query www.hp.com. A
IN
[1345129616] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
[1345129616] unbound[19900:0] info: resolving www.hp.com. A IN
[1345129616] unbound[19900:0] info: priming . IN NS
[1345129616] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
[1345129616] unbound[19900:0] info: iterator operate: query . NS IN
[1345129616] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129616] unbound[19900:0] info: sending query: . NS IN
[1345129616] unbound[19900:0] debug: sending to target: <.> 198.41.0.4#53
[1345129616] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1533 val=33196
[1345129617] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129617] unbound[19900:0] info: iterator operate: query . NS IN
[1345129617] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129617] unbound[19900:0] info: sending query: . NS IN
[1345129617] unbound[19900:0] debug: sending to target: <.> 128.63.2.53#53
[1345129617] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1762 val=33196
[1345129617] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129617] unbound[19900:0] info: iterator operate: query . NS IN
[1345129617] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129617] unbound[19900:0] info: sending query: . NS IN
[1345129617] unbound[19900:0] debug: sending to target: <.>
192.203.230.10#53
[1345129617] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1991 val=33196
[1345129618] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129618] unbound[19900:0] info: iterator operate: query . NS IN
[1345129618] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129618] unbound[19900:0] info: sending query: . NS IN
[1345129618] unbound[19900:0] debug: sending to target: <.>
192.203.230.10#53
[1345129618] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1991 val=33196
[1345129619] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=1991 val=33196
[1345129620] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129620] unbound[19900:0] info: iterator operate: query . NS IN
[1345129620] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129620] unbound[19900:0] info: sending query: . NS IN
[1345129620] unbound[19900:0] debug: sending to target: <.> 192.58.128.30#53
[1345129620] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2220 val=33196
[1345129620] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129620] unbound[19900:0] info: iterator operate: query . NS IN
[1345129620] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129620] unbound[19900:0] info: sending query: . NS IN
[1345129620] unbound[19900:0] debug: sending to target: <.> 192.5.5.241#53
[1345129620] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2449 val=33196
[1345129621] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129621] unbound[19900:0] info: iterator operate: query . NS IN
[1345129621] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129621] unbound[19900:0] info: sending query: . NS IN
[1345129621] unbound[19900:0] debug: sending to target: <.> 198.41.0.4#53
[1345129621] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2449 val=33196
[1345129623] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129623] unbound[19900:0] info: iterator operate: query . NS IN
[1345129623] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129623] unbound[19900:0] info: sending query: . NS IN
[1345129623] unbound[19900:0] debug: sending to target: <.> 192.5.5.241#53
[1345129623] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2449 val=33196
[1345129624] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129624] unbound[19900:0] info: iterator operate: query . NS IN
[1345129624] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129624] unbound[19900:0] info: sending query: . NS IN
[1345129624] unbound[19900:0] debug: sending to target: <.> 193.0.14.129#53
[1345129624] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2678 val=33196
[1345129625] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129625] unbound[19900:0] info: iterator operate: query . NS IN
[1345129625] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129625] unbound[19900:0] info: sending query: . NS IN
[1345129625] unbound[19900:0] debug: sending to target: <.> 192.58.128.30#53
[1345129625] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2678 val=33196
[1345129626] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129626] unbound[19900:0] info: iterator operate: query . NS IN
[1345129626] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129626] unbound[19900:0] info: sending query: . NS IN
[1345129626] unbound[19900:0] debug: sending to target: <.> 128.8.10.90#53
[1345129626] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=2907 val=33196
[1345129627] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129627] unbound[19900:0] info: iterator operate: query . NS IN
[1345129627] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129627] unbound[19900:0] info: sending query: . NS IN
[1345129627] unbound[19900:0] debug: sending to target: <.> 202.12.27.33#53
[1345129627] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3136 val=33196
[1345129628] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129628] unbound[19900:0] info: iterator operate: query . NS IN
[1345129628] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129628] unbound[19900:0] info: sending query: . NS IN
[1345129628] unbound[19900:0] debug: sending to target: <.> 128.8.10.90#53
[1345129628] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3136 val=33196
[1345129629] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129629] unbound[19900:0] info: iterator operate: query . NS IN
[1345129629] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129629] unbound[19900:0] info: sending query: . NS IN
[1345129629] unbound[19900:0] debug: sending to target: <.> 128.63.2.53#53
[1345129629] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3136 val=33196
[1345129630] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3136 val=33196
[1345129631] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129631] unbound[19900:0] info: iterator operate: query . NS IN
[1345129631] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129631] unbound[19900:0] info: sending query: . NS IN
[1345129631] unbound[19900:0] debug: sending to target: <.> 192.112.36.4#53
[1345129631] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3365 val=33196
[1345129632] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129632] unbound[19900:0] info: iterator operate: query . NS IN
[1345129632] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129632] unbound[19900:0] info: sending query: . NS IN
[1345129632] unbound[19900:0] debug: sending to target: <.>
192.228.79.201#53
[1345129632] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3594 val=33196
[1345129632] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129632] unbound[19900:0] info: iterator operate: query . NS IN
[1345129632] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129632] unbound[19900:0] info: sending query: . NS IN
[1345129632] unbound[19900:0] debug: sending to target: <.>
192.228.79.201#53
[1345129632] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3594 val=33196
[1345129634] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_reply event:module_event_noreply
[1345129634] unbound[19900:0] info: iterator operate: query . NS IN
[1345129634] unbound[19900:0] info: processQueryTargets: . NS IN
[1345129634] unbound[19900:0] debug: request has exceeded the maximum
number of sends with 17
[1345129634] unbound[19900:0] debug: return error response SERVFAIL
[1345129634] unbound[19900:0] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_moddone
[1345129634] unbound[19900:0] info: validator operate: query . NS IN
[1345129634] unbound[19900:0] debug: iterator[module 1] operate:
extstate:module_wait_subquery event:module_event_pass
[1345129634] unbound[19900:0] info: iterator operate: query www.hp.com. A IN
[1345129634] unbound[19900:0] info: processQueryTargets: www.hp.com. A IN
[1345129634] unbound[19900:0] debug: Failed to get a delegation, giving up
[1345129634] unbound[19900:0] debug: return error response SERVFAIL
[1345129634] unbound[19900:0] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
[1345129634] unbound[19900:0] info: validator operate: query www.hp.com. A
IN
[1345129634] unbound[19900:0] debug: cache memory msg=33040 rrset=33040
infra=3594 val=33196
################################# END LOG FILE
#################################


############################## MANUAL COMMANDS
##############################
* $ dnsq a www.hp.com 198.41.0.4*
1 www.hp.com:
500 bytes, 1+0+13+14 records, response, noerror
query: 1 www.hp.com
authority: com 172800 NS a.gtld-servers.net
authority: com 172800 NS b.gtld-servers.net
authority: com 172800 NS c.gtld-servers.net
authority: com 172800 NS d.gtld-servers.net
authority: com 172800 NS e.gtld-servers.net
authority: com 172800 NS f.gtld-servers.net
authority: com 172800 NS g.gtld-servers.net
authority: com 172800 NS h.gtld-servers.net
authority: com 172800 NS i.gtld-servers.net
authority: com 172800 NS j.gtld-servers.net
authority: com 172800 NS k.gtld-servers.net
authority: com 172800 NS l.gtld-servers.net
authority: com 172800 NS m.gtld-servers.net
additional: a.gtld-servers.net 172800 AAAA 2001:503:a83e::2:30
additional: a.gtld-servers.net 172800 A 192.5.6.30
additional: b.gtld-servers.net 172800 AAAA 2001:503:231d::2:30
additional: b.gtld-servers.net 172800 A 192.33.14.30
additional: c.gtld-servers.net 172800 A 192.26.92.30
additional: d.gtld-servers.net 172800 A 192.31.80.30
additional: e.gtld-servers.net 172800 A 192.12.94.30
additional: f.gtld-servers.net 172800 A 192.35.51.30
additional: g.gtld-servers.net 172800 A 192.42.93.30
additional: h.gtld-servers.net 172800 A 192.54.112.30
additional: i.gtld-servers.net 172800 A 192.43.172.30
additional: j.gtld-servers.net 172800 A 192.48.79.30
additional: k.gtld-servers.net 172800 A 192.52.178.30
additional: l.gtld-servers.net 172800 A 192.41.162.30
* $ dnsq a www.hp.com 192.5.6.30*
1 www.hp.com:
232 bytes, 1+0+6+6 records, response, noerror
query: 1 www.hp.com
authority: hp.com 172800 NS ns1.hp.com
authority: hp.com 172800 NS ns2.hp.com
authority: hp.com 172800 NS ns3.hp.com
authority: hp.com 172800 NS ns4.hp.com
authority: hp.com 172800 NS ns5.hp.com
authority: hp.com 172800 NS ns6.hp.com
additional: ns1.hp.com 172800 A 15.219.145.12
additional: ns2.hp.com 172800 A 15.219.160.12
additional: ns3.hp.com 172800 A 15.211.192.12
additional: ns4.hp.com 172800 A 15.203.224.14
additional: ns5.hp.com 172800 A 15.195.192.37
additional: ns6.hp.com 172800 A 15.195.208.12
* $ dnsq a www.hp.com 15.219.145.12*
1 www.hp.com:
61 bytes, 1+1+0+0 records, response, authoritative, noerror
query: 1 www.hp.com
answer: www.hp.com 100 CNAME www.hpgtm.nsatc.net
* $ dnsq a www.hpgtm.nsatc.net 198.41.0.4*
1 www.hpgtm.nsatc.net:
506 bytes, 1+0+13+14 records, response, noerror
query: 1 www.hpgtm.nsatc.net
authority: net 172800 NS a.gtld-servers.net
authority: net 172800 NS b.gtld-servers.net
authority: net 172800 NS c.gtld-servers.net
authority: net 172800 NS d.gtld-servers.net
authority: net 172800 NS e.gtld-servers.net
authority: net 172800 NS f.gtld-servers.net
authority: net 172800 NS g.gtld-servers.net
authority: net 172800 NS h.gtld-servers.net
authority: net 172800 NS i.gtld-servers.net
authority: net 172800 NS j.gtld-servers.net
authority: net 172800 NS k.gtld-servers.net
authority: net 172800 NS l.gtld-servers.net
authority: net 172800 NS m.gtld-servers.net
additional: a.gtld-servers.net 172800 AAAA 2001:503:a83e::2:30
additional: a.gtld-servers.net 172800 A 192.5.6.30
additional: b.gtld-servers.net 172800 AAAA 2001:503:231d::2:30
additional: b.gtld-servers.net 172800 A 192.33.14.30
additional: c.gtld-servers.net 172800 A 192.26.92.30
additional: d.gtld-servers.net 172800 A 192.31.80.30
additional: e.gtld-servers.net 172800 A 192.12.94.30
additional: f.gtld-servers.net 172800 A 192.35.51.30
additional: g.gtld-servers.net 172800 A 192.42.93.30
additional: h.gtld-servers.net 172800 A 192.54.112.30
additional: i.gtld-servers.net 172800 A 192.43.172.30
additional: j.gtld-servers.net 172800 A 192.48.79.30
additional: k.gtld-servers.net 172800 A 192.52.178.30
additional: l.gtld-servers.net 172800 A 192.41.162.30
* $ dnsq a www.hpgtm.nsatc.net 192.5.6.30*
1 www.hpgtm.nsatc.net:
264 bytes, 1+0+7+7 records, response, noerror
query: 1 www.hpgtm.nsatc.net
authority: nsatc.net 172800 NS a.ns.nsatc.net
authority: nsatc.net 172800 NS b.ns.nsatc.net
authority: nsatc.net 172800 NS c.ns.nsatc.net
authority: nsatc.net 172800 NS d.ns.nsatc.net
authority: nsatc.net 172800 NS e.ns.nsatc.net
authority: nsatc.net 172800 NS j.ns.nsatc.net
authority: nsatc.net 172800 NS l.ns.nsatc.net
additional: a.ns.nsatc.net 172800 A 199.93.44.45
additional: b.ns.nsatc.net 172800 A 207.123.33.51
additional: c.ns.nsatc.net 172800 A 4.23.51.51
additional: d.ns.nsatc.net 172800 A 205.128.93.51
additional: e.ns.nsatc.net 172800 A 212.187.162.134
additional: j.ns.nsatc.net 172800 A 192.221.69.49
additional: l.ns.nsatc.net 172800 A 8.255.48.47
* $ dnsq a www.hpgtm.nsatc.net 199.93.44.45*
1 www.hpgtm.nsatc.net:
174 bytes, 1+2+3+3 records, response, authoritative, noerror
query: 1 www.hpgtm.nsatc.net
answer: www.hpgtm.nsatc.net 120 A 15.192.45.26
answer: www.hpgtm.nsatc.net 120 A 15.192.40.12
authority: nsatc.net 172800 NS d.ns.nsatc.net
authority: nsatc.net 172800 NS us-ga-1.ns.nsatc.net
authority: nsatc.net 172800 NS c.ns.nsatc.net
additional: d.ns.nsatc.net 172800 A 205.128.93.51
additional: us-ga-1.ns.nsatc.net 172800 A 204.160.105.51
additional: c.ns.nsatc.net 172800 A 4.23.51.51

############################ END MANUAL COMMANDS
############################
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20120816/a08d3729/attachment.htm>

More information about the Unbound-users mailing list