[Pdns-users] 1 sec delay before DNS-answer at pdns-recursor

Sun Jun 23 16:44:31 UTC 2013

What about giving the full dig output too?  My bet is you're actually
experiencing some sort of huge delay starting up dig or resolving
"localhost", use @127.0.0.1 instead and see if the time goes away.
Does your /etc/hosts contain 'localhost'?  Have you modified your
nsswitch.conf? (Assuming standard *nix like system)

On Sun, Jun 23, 2013 at 3:58 AM, Shamus Smith <smithshamus at yahoo.de> wrote:
> Hello Bert,
>
>> > Any ideas why it takes so long?
>>
>> Rerun with --trace enabled and check what is happening. With some study,
>> it should be clear what it is waiting for.
>
> did that already before, but still did not found anything helpful there.
> Below is a new trace.
> btw, I am using 3.5.1 (package pdns-recursor-3.5.1-1.el6.x86_64).
>
> Thanks,
>  Shamus
>
> - /etc/init.d/pdns-recursor start
> Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS recursor 3.5.1 (C)
> 2001-2013 PowerDNS.COM BV (May  3 2013, 20:04:33, gcc 4.4.7 20120313 (Red
> Hat 4.4.7-3)) starting up
> Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS comes with ABSOLUTELY
> NO WARRANTY. This is free software, and you are welcome to redistribute it
> according to the terms of the GPL version 2.
> Jun 23 12:30:12 server pdns_recursor[11064]: Operating in 64 bits mode
> Jun 23 12:30:12 server pdns_recursor[11064]: Reading random entropy from
> '/dev/urandom'
> Jun 23 12:30:12 server pdns_recursor[11064]: Only allowing queries from:
> 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16,
> 172.16.0.0/12, ::1/128, fe80::/10
> Jun 23 12:30:12 server pdns_recursor[11064]: Will not send queries to:
> 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16,
> 172.16.0.0/12, ::1/128, fe80::/10, 0.0.0.0, ::
> Jun 23 12:30:12 server pdns_recursor[11064]: NOT using IPv6 for outgoing
> queries - set 'query-local-address6=::' to enable
> Jun 23 12:30:12 server pdns_recursor[11064]: Redirecting queries for zone
> '.' to: 8.8.8.8:53
> Jun 23 12:30:12 server pdns_recursor[11064]: Inserting rfc 1918 private
> space zones
> Jun 23 12:30:12 server pdns_recursor[11064]: Not decreasing socket buffer
> size from 229376 to 200000
> Jun 23 12:30:12 server pdns_recursor[11064]: Listening for UDP queries on
> 127.0.0.1:53
> Jun 23 12:30:12 server pdns_recursor[11064]: Enabled TCP data-ready filter
> for (slight) DoS protection
> Jun 23 12:30:12 server pdns_recursor[11064]: Listening for TCP queries on
> 127.0.0.1:53
> Jun 23 12:30:12 server pdns_recursor[11064]: Calling daemonize, going to
> background
> Jun 23 12:30:12 server pdns_recursor[11065]: Set effective group id to 497
> Jun 23 12:30:12 server pdns_recursor[11065]: Set effective user id to 497
> Jun 23 12:30:12 server pdns_recursor[11065]: Launching 2 threads
> Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root
> hints
> Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root
> hints
> Jun 23 12:30:12 server pdns_recursor[11065]: Enabled 'epoll' multiplexer
> Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS',
> trying to find an appropriate NS record
> Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS',
> trying to find an appropriate NS record
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done,
> have 1 NS to contact
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done,
> have 1 NS to contact
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers:
> -8.8.8.8:53(0.00ms)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS
> '-8.8.8.8:53' (1/1)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded
> nameserver(s)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53
> to: 8.8.8.8
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers:
> -8.8.8.8:53(0.00ms)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS
> '-8.8.8.8:53' (1/1)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded
> nameserver(s)
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53
> to: 8.8.8.8
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking
> '.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking
> '.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Got 13 answers from
> -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 6ms
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|d.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|l.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|c.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|g.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|h.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|b.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: Got 13 answers from
> -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 6ms
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|d.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|l.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|c.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|g.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|h.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|b.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|f.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|m.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|k.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|a.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|j.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|i.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|e.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: determining status after
> receiving this packet
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'd.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'l.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'c.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'g.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'h.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'b.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'f.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'm.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'k.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'a.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'j.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'i.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'e.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: status=got results, this
> level of recursion done
> Jun 23 12:30:12 server pdns_recursor[11065]: Refreshed . records
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|f.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|m.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|k.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|a.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|j.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|i.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
> '.|NS|e.root-servers.net.' from '.' nameservers? YES!
> Jun 23 12:30:12 server pdns_recursor[11065]: .: determining status after
> receiving this packet
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'd.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'l.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'c.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'g.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'h.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'b.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'f.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'm.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'k.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'a.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'j.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'i.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: answer is in: resolved to
> 'e.root-servers.net.|NS'
> Jun 23 12:30:12 server pdns_recursor[11065]: .: status=got results, this
> level of recursion done
> Jun 23 12:30:12 server pdns_recursor[11065]: Refreshed . records
>
> - 1st lookup: dig +short www.google.com @localhost
> Jun 23 12:34:10 server pdns_recursor[11065]: 0 [3] question for
> 'www.google.com.|A' from 127.0.0.1
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Looking
> for CNAME cache hit of 'www.google.com.|CNAME'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: No CNAME
> cache hit of 'www.google.com.|CNAME' found
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: No cache
> hit for 'www.google.com.|A', trying to find an appropriate NS record
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Cache
> consultations done, have 1 NS to contact
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.:
> Nameservers: -8.8.8.8:53(0.23ms)
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Trying to
> resolve NS '-8.8.8.8:53' (1/1)
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Domain has
> hardcoded nameserver(s)
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Resolved
> '.' NS -8.8.8.8:53 to: 8.8.8.8
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Trying IP
> 8.8.8.8:53, asking 'www.google.com.|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: Got 5
> answers from -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 3ms
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: accept
> answer 'www.google.com.|A|173.194.112.242' from '.' nameservers? YES!
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: accept
> answer 'www.google.com.|A|173.194.112.243' from '.' nameservers? YES!
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: accept
> answer 'www.google.com.|A|173.194.112.240' from '.' nameservers? YES!
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: accept
> answer 'www.google.com.|A|173.194.112.241' from '.' nameservers? YES!
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: accept
> answer 'www.google.com.|A|173.194.112.244' from '.' nameservers? YES!
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.:
> determining status after receiving this packet
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: answer is
> in: resolved to '173.194.112.242|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: answer is
> in: resolved to '173.194.112.243|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: answer is
> in: resolved to '173.194.112.240|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: answer is
> in: resolved to '173.194.112.241|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: answer is
> in: resolved to '173.194.112.244|A'
> Jun 23 12:34:10 server pdns_recursor[11065]: [3] www.google.com.: status=got
> results, this level of recursion done
> Jun 23 12:34:10 server pdns_recursor[11065]: 0 [3] answer to question
> 'www.google.com.|A': 5 answers, 0 additional, took 1 packets, 0 throttled, 0
> timeouts, 0 tcp connections, rcode=0
>
> - 2nd lookup: dig +short www.google.com @localhost
> Jun 23 12:34:21 server pdns_recursor[11065]: 0 question answered from packet
> cache from 127.0.0.1
>
>
> _______________________________________________
> Pdns-users mailing list
> Pdns-users at mailman.powerdns.com
> http://mailman.powerdns.com/mailman/listinfo/pdns-users
>

-- 

"Genius might be described as a supreme capacity for getting its possessors
into trouble of all kinds."
-- Samuel Butler