Maintained by: NLnet Labs

[Unbound-users] Can't resolve m.facebook.com

Attila Nagy
Thu Feb 9 08:29:42 CET 2012


Hi,

Running unbound r2580, I can't resolve m.facebook.com. I get SERVFAIL back.
The server was running for some time, so it's not in a fresh state. It 
seems the problem is that facebook DNS servers time out on AAAA records, 
so unbound gets the false assumption that they are unavailable.

Here are the verbose (level 4) logs while trying to resolve the name:
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: answer from the cache 
failed
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: start
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: validator[module 0] 
operate: extstate:module_state_initial event:module_event_new
Feb  9 08:24:33 cns04k unbound: [32693:3] info: validator operate: query 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: validator: pass to next 
module
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: validator 
module exit state is module_wait_module
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: python module 
exit state is module_wait_module
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iterator[module 2] 
operate: extstate:module_state_initial event:module_event_pass
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: process_request: new 
external request event
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state INIT REQUEST STATE
Feb  9 08:24:33 cns04k unbound: [32693:3] info: resolving 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: request has dependency 
depth of 0
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: cache delegation 
returns delegpt
Feb  9 08:24:33 cns04k unbound: [32693:3] info: 
DelegationPoint<facebook.com.>: 5 names (0 missing), 5 addrs (0 result, 
5 avail) cacheNS
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns1.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns2.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns3.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns5.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns4.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.63.186.49 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 66.220.145.65 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 66.220.151.20 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 204.74.67.132 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 204.74.66.132 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state INIT REQUEST STATE (stage 2)
Feb  9 08:24:33 cns04k unbound: [32693:3] info: resolving (init part 
2):  m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state INIT REQUEST STATE (stage 3)
Feb  9 08:24:33 cns04k unbound: [32693:3] info: resolving (init part 
3):  m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state QUERY TARGETS STATE
Feb  9 08:24:33 cns04k unbound: [32693:3] info: processQueryTargets: 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: processQueryTargets: 
targetqueries 0, currentqueries 0 sentcount 0
Feb  9 08:24:33 cns04k unbound: [32693:3] info: 
DelegationPoint<facebook.com.>: 5 names (0 missing), 5 addrs (0 result, 
5 avail) cacheNS
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns1.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns2.facebook.com. * A AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns3.facebook.com. * A AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns5.facebook.com. * A AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   ns4.facebook.com. * A AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.63.186.49 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 66.220.145.65 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 66.220.151.20 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 204.74.67.132 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 204.74.66.132 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: attempt to get extra 3 
targets
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: selrtt 376
Feb  9 08:24:33 cns04k unbound: [32693:3] info: sending query: 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: sending to target: 
<facebook.com.> 69.63.186.49#53
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: dnssec status: not expected
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: EDNS lookup known=0 vs=0
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: serviced query UDP 
timeout=376 msec
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: inserted new pending 
reply id=6743
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: opened UDP if=0 port=50044
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: comm point start 
listening 13
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: iterator 
module exit state is module_wait_reply
Feb  9 08:24:33 cns04k unbound: [32693:3] info: mesh_run: end 1 
recursion states (1 with reply, 0 detached), 1 waiting replies, 0 
recursion replies sent, 0 replies dropped, 0 states jostled out
Feb  9 08:24:33 cns04k unbound: [32693:3] info: 0RDd mod2 rep 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: cache memory 
msg=223346769 rrset=505413687 infra=2802115 val=1072421
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: answer cb
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: Incoming reply id = 6743
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: Incoming reply addr = 
ip4 69.63.186.49 port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: lookup size is 1 entries
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: received udp reply.
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: udp message[113:0] 
674380000001000000020003016D0866616365626F6F6B03636F6D0000010001C00C0002000100000E10000704676C6231C00EC00C0002000100000E10000704676C6232C00EC02C0001000100000E10000445ABEF0AC03F0001000100000E10000445ABFF0A0000291000000080000000
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: outnet handle udp reply
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: serviced query: EDNS 
works for ip4 69.63.186.49 port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: measured roundtrip at 
113 msec
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: svcd callbacks start
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: worker svcd callback 
for qstate 0x8025ff080
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: start
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iterator[module 2] 
operate: extstate:module_wait_reply event:module_event_reply
Feb  9 08:24:33 cns04k unbound: [32693:3] info: iterator operate: query 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: process_response: new 
external response event
Feb  9 08:24:33 cns04k unbound: [32693:3] info: scrub for facebook.com. 
NS IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: response for 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: reply from 
<facebook.com.> 69.63.186.49#53
Feb  9 08:24:33 cns04k unbound: [32693:3] info: incoming scrubbed 
packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
Feb  9 08:24:33 cns04k ;; flags: qr ; QUERY: 1, ANSWER: 0, AUTHORITY: 2, 
ADDITIONAL: 2
Feb  9 08:24:33 cns04k ;; QUESTION SECTION:
Feb  9 08:24:33 cns04k ;; m.facebook.com.       IN      A
Feb  9 08:24:33 cns04k ;; ANSWER SECTION:
Feb  9 08:24:33 cns04k ;; AUTHORITY SECTION:
Feb  9 08:24:33 cns04k m.facebook.com.  3600    IN      NS      
glb1.facebook.com.
Feb  9 08:24:33 cns04k m.facebook.com.  3600    IN      NS      
glb2.facebook.com.
Feb  9 08:24:33 cns04k ;; ADDITIONAL SECTION:
Feb  9 08:24:33 cns04k glb1.facebook.com.       3600    IN      A       
69.171.239.10
Feb  9 08:24:33 cns04k glb2.facebook.com.       3600    IN      A       
69.171.255.10
Feb  9 08:24:33 cns04k ;; Query time: 0 msec
Feb  9 08:24:33 cns04k ;; WHEN: Thu Jan  1 01:00:00 1970
Feb  9 08:24:33 cns04k ;; MSG SIZE  rcvd: 102
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state QUERY RESPONSE STATE
Feb  9 08:24:33 cns04k unbound: [32693:3] info: query response was REFERRAL
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found in cache 
glb2.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found in cache 
glb1.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: 
DelegationPoint<m.facebook.com.>: 2 names (0 missing), 2 addrs (0 
result, 2 avail) parentNS
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   glb2.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   glb1.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.171.255.10 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.171.239.10 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: cleared outbound list 
for next round
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: iter_handle processing 
q with state QUERY TARGETS STATE
Feb  9 08:24:33 cns04k unbound: [32693:3] info: processQueryTargets: 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: processQueryTargets: 
targetqueries 0, currentqueries 0 sentcount 0
Feb  9 08:24:33 cns04k unbound: [32693:3] info: 
DelegationPoint<m.facebook.com.>: 2 names (0 missing), 2 addrs (0 
result, 2 avail) parentNS
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   glb2.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] info:   glb1.facebook.com. * A 
AAAA
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.171.255.10 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    ip4 69.171.239.10 
port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: attempt to get extra 3 
targets
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: servselect ip4 
69.171.239.10 port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    rtt=119000 LAME 
DNSSEC_LAME REC_LAME
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: servselect ip4 
69.171.255.10 port 53 (len 16)
Feb  9 08:24:33 cns04k unbound: [32693:3] debug:    rtt=119000 LAME 
DNSSEC_LAME REC_LAME
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: No more query targets, 
attempting last resort
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found in cache 
glb2.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found in cache 
glb1.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found parent-side 
glb2.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found parent-side 
glb2.facebook.com. AAAA IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found parent-side 
glb1.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] info: found parent-side 
glb1.facebook.com. AAAA IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: out of query targets -- 
returning SERVFAIL
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: store error response in 
message cache
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: return error response 
SERVFAIL
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: iterator 
module exit state is module_finished
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: python module 
exit state is module_finished
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: validator[module 0] 
operate: extstate:module_wait_module event:module_event_moddone
Feb  9 08:24:33 cns04k unbound: [32693:3] info: validator operate: query 
m.facebook.com. A IN
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: validator: nextmodule 
returned
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: cannot validate 
non-answer, rcode SERVFAIL
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: mesh_run: validator 
module exit state is module_finished
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: query took 0.113802 sec
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: pythonmod: clear, id: 
1, pq:80936C4E8
Feb  9 08:24:33 cns04k unbound: [32693:3] info: mesh_run: end 0 
recursion states (0 with reply, 0 detached), 0 waiting replies, 1 
recursion replies sent, 0 replies dropped, 0 states jostled out
Feb  9 08:24:33 cns04k unbound: [32693:3] info: average recursion 
processing time 0.113802 sec
Feb  9 08:24:33 cns04k unbound: [32693:3] info: histogram of recursion 
processing times
Feb  9 08:24:33 cns04k unbound: [32693:3] info: [25%]=0 median[50%]=0 
[75%]=0
Feb  9 08:24:33 cns04k unbound: [32693:3] info: lower(secs) upper(secs) 
recursions
Feb  9 08:24:33 cns04k unbound: [32693:3] info:    0.065536    0.131072 1
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: cache memory 
msg=223346769 rrset=505413687 infra=2802115 val=1072421
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: svcd callbacks end
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: close of port 50044
Feb  9 08:24:33 cns04k unbound: [32693:3] debug: close fd 13