Maintained by: NLnet Labs

[Unbound-users] bodybuilding.com issues?

Haw Loeung
Wed Jan 6 03:04:23 CET 2010


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
_______________________________________________________________________
  
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 490 bytes
Desc: This is a digitally signed message part.
URL: <http://unbound.nlnetlabs.nl/pipermail/unbound-users/attachments/20100106/b6bab9e4/attachment.pgp>