Hi Guys, Is anyone else experiencing intermittent DNS issues with bodybuilding.com?
With verbosity set to 99, here's what I see in our logs:
===
Jan 06 12:59:37 unbound[16172:0] debug: remote control operation completed
Jan 06 12:59:37 unbound[16172:0] debug: close fd 25
Jan 06 12:59:37 unbound[16172:1] debug: answer from the cache failed
Jan 06 12:59:37 unbound[16172:1] debug: udp request from ip4 127.0.0.1 port
39580 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: mesh_run: start
Jan 06 12:59:37 unbound[16172:1] debug: validator[module 0] operate:
extstate:module_state_initial event:module_event_new
Jan 06 12:59:37 unbound[16172:1] info: validator operate: query
<bodybuilding.com. ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: validator: pass to next module
Jan 06 12:59:37 unbound[16172:1] debug: mesh_run: validator module exit state
is
module_wait_module
Jan 06 12:59:37 unbound[16172:1] debug: iterator[module 1] operate:
extstate:module_state_initial event:module_event_pass
Jan 06 12:59:37 unbound[16172:1] debug: process_request: new external request
event
Jan 06 12:59:37 unbound[16172:1] debug: iter_handle processing q with state
INIT REQUEST
STATE
Jan 06 12:59:37 unbound[16172:1] info: resolving <bodybuilding.com. ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: request has dependency depth of 0
Jan 06 12:59:37 unbound[16172:1] debug: cache delegation returns delegpt
Jan 06 12:59:37 unbound[16172:1] info: DelegationPoint<bodybuilding.com.>: 5
names (5
missing), 5 addrs (0 result, 5 avail)
Jan 06 12:59:37 unbound[16172:1] info: ns4.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns1.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns3.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns5.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns2.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.124.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.127.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.126.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.94.148.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.125.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: iter_handle processing q with state
INIT REQUEST
STATE (stage 2)
Jan 06 12:59:37 unbound[16172:1] info: resolving (init part 2):
<bodybuilding.com. ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: iter_handle processing q with state
INIT REQUEST
STATE (stage 3)
Jan 06 12:59:37 unbound[16172:1] info: resolving (init part 3):
<bodybuilding.com. ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: iter_handle processing q with state
QUERY
TARGETS STATE
Jan 06 12:59:37 unbound[16172:1] info: processQueryTargets: <bodybuilding.com.
ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: processQueryTargets: targetqueries 0,
currentqueries 0
Jan 06 12:59:37 unbound[16172:1] info: DelegationPoint<bodybuilding.com.>: 5
names (5
missing), 5 addrs (0 result, 5 avail)
Jan 06 12:59:37 unbound[16172:1] info: ns4.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns1.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns3.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns5.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] info: ns2.bodybuilding.com. A
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.124.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.127.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.126.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.94.148.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: ip4 208.80.125.4 port 53 (len 16)
Jan 06 12:59:37 unbound[16172:1] debug: attempt to get extra 3 targets
Jan 06 12:59:37 unbound[16172:1] debug: servselect ip4 208.94.148.4 port 53
(len 16)
Jan 06 12:59:37 unbound[16172:1] debug: rtt=201
Jan 06 12:59:37 unbound[16172:1] debug: servselect ip4 208.80.126.4 port 53
(len 16)
Jan 06 12:59:37 unbound[16172:1] debug: rtt=628
Jan 06 12:59:37 unbound[16172:1] debug: servselect ip4 208.80.127.4 port 53
(len 16)
Jan 06 12:59:37 unbound[16172:1] debug: rtt=632
Jan 06 12:59:37 unbound[16172:1] debug: servselect ip4 208.80.124.4 port 53
(len 16)
Jan 06 12:59:37 unbound[16172:1] debug: rtt=619
Jan 06 12:59:37 unbound[16172:1] debug: Bad choices, trying to get more choice
Jan 06 12:59:37 unbound[16172:1] debug: querying for next missing target
Jan 06 12:59:37 unbound[16172:1] debug: out of query targets -- returning
SERVFAIL
Jan 06 12:59:37 unbound[16172:1] debug: store error response in message cache
Jan 06 12:59:37 unbound[16172:1] debug: return error response SERVFAIL
Jan 06 12:59:37 unbound[16172:1] debug: mesh_run: iterator module exit state is
module_finished
Jan 06 12:59:37 unbound[16172:1] debug: validator[module 0] operate:
extstate:module_wait_module event:module_event_moddone
Jan 06 12:59:37 unbound[16172:1] info: validator operate: query
<bodybuilding.com. ANY IN>
Jan 06 12:59:37 unbound[16172:1] debug: validator: nextmodule returned
Jan 06 12:59:37 unbound[16172:1] debug: cannot validate non-answer, rcode
SERVFAIL
Jan 06 12:59:37 unbound[16172:1] debug: mesh_run: validator module exit state
is
module_finished
Jan 06 12:59:37 unbound[16172:1] debug: query took 0.000000 sec
Jan 06 12:59:37 unbound[16172:1] info: mesh_run: end 1 recursion states (1 with
reply, 0
detached), 33 waiting replies, 221508645 recursion replies sent, 0 replies
dropped, 0 states
jostled out
Jan 06 12:59:37 unbound[16172:1] info: average recursion processing time
3.264751 sec
Jan 06 12:59:37 unbound[16172:1] info: histogram of recursion processing times
Jan 06 12:59:37 unbound[16172:1] info: [25%]=0.00063075 median[50%]=0.0491874
[75%]=0.124386
Jan 06 12:59:37 unbound[16172:1] info: lower(secs) upper(secs) recursions
Jan 06 12:59:37 unbound[16172:1] info: 0.000000 0.000001 2546906
Jan 06 12:59:37 unbound[16172:1] info: 0.000002 0.000004 2
Jan 06 12:59:37 unbound[16172:1] info: 0.000004 0.000008 41028
Jan 06 12:59:37 unbound[16172:1] info: 0.000008 0.000016 7927
Jan 06 12:59:37 unbound[16172:1] info: 0.000016 0.000032 5838
Jan 06 12:59:37 unbound[16172:1] info: 0.000032 0.000064 1954651
Jan 06 12:59:37 unbound[16172:1] info: 0.000064 0.000128 1440477
Jan 06 12:59:37 unbound[16172:1] info: 0.000128 0.000256 688009
Jan 06 12:59:37 unbound[16172:1] info: 0.000256 0.000512 360727
Jan 06 12:59:37 unbound[16172:1] info: 0.000512 0.001024 28173322
Jan 06 12:59:37 unbound[16172:1] info: 0.001024 0.002048 14329361
Jan 06 12:59:37 unbound[16172:1] info: 0.002048 0.004096 5632398
Jan 06 12:59:37 unbound[16172:1] info: 0.004096 0.008192 1276142
Jan 06 12:59:37 unbound[16172:1] info: 0.008192 0.016384 6026449
Jan 06 12:59:37 unbound[16172:1] info: 0.016384 0.032768 7256098
Jan 06 12:59:37 unbound[16172:1] info: 0.032768 0.065536 2984875
Jan 06 12:59:37 unbound[16172:1] info: 0.065536 0.131072 1808063
Jan 06 12:59:37 unbound[16172:1] info: 0.131072 0.262144 96522535
Jan 06 12:59:37 unbound[16172:1] info: 0.262144 0.524288 26305628
Jan 06 12:59:37 unbound[16172:1] info: 0.524288 1.000000 5902840
Jan 06 12:59:37 unbound[16172:1] info: 1.000000 2.000000 4107265
Jan 06 12:59:37 unbound[16172:1] info: 2.000000 4.000000 4740679
Jan 06 12:59:37 unbound[16172:1] info: 4.000000 8.000000 3821946
Jan 06 12:59:37 unbound[16172:1] info: 8.000000 16.000000 1337149
Jan 06 12:59:37 unbound[16172:1] info: 16.000000 32.000000 759638
Jan 06 12:59:37 unbound[16172:1] info: 32.000000 64.000000 782507
Jan 06 12:59:37 unbound[16172:1] info: 64.000000 128.000000 1019874
Jan 06 12:59:37 unbound[16172:1] info: 128.000000 256.000000 1015930
Jan 06 12:59:37 unbound[16172:1] info: 256.000000 512.000000 477832
Jan 06 12:59:37 unbound[16172:1] info: 512.000000 1024.000000 159123
Jan 06 12:59:37 unbound[16172:1] info: 1024.000000 2048.000000 23345
Jan 06 12:59:37 unbound[16172:1] info: 2048.000000 4096.000000 81
Jan 06 12:59:37 unbound[16172:1] info: 0RDd mod1 rep
<190.133.198.69.in-addr.arpa. PTR
IN>
Jan 06 12:59:37 unbound[16172:0] debug: new control connection from ip4
127.0.0.1 port
45700 (len 16)
Jan 06 12:59:37 unbound[16172:0] debug: comm point stop listening 25
Jan 06 12:59:37 unbound[16172:0] debug: comm point start listening 25
Jan 06 12:59:37 unbound[16172:1] debug: cache memory msg=958398477
rrset=1916797124 infra=4299409 val=1088875
Jan 06 12:59:37 unbound[16172:0] debug: remote control connection authenticated
Jan 06 12:59:37 unbound[16172:0] info: control cmd: verbosity 0
===
Any ideas on what is happening? Delegation seems correct, domain doesn't
seem to be misconfigured from what I can see.
Thanks in advance.
Regards,
Haw
--
Haw Loeung
Systems Administrator
TPG Internet
http://www.tpg.com.au
_______________________________________________________________________
signature.asc
Description: This is a digitally signed message part.
_______________________________________________ Unbound-users mailing list [email protected] http://unbound.nlnetlabs.nl/mailman/listinfo/unbound-users
