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

Sun Jun 23 10:58:37 UTC 2013

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.powerdns.com/pipermail/pdns-users/attachments/20130623/41d50069/attachment-0001.html>