Maintained by: NLnet Labs

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

Attila Nagy
Thu Feb 9 08:49:37 CET 2012


"Thanks for the report, the feature itself could complement the local-data
facility nicely, but it does not seem to be necessary now and we have a 
strict
no-features guideline."
Well, here is my +1 for 
http://www.nlnetlabs.nl/bugs-script/show_bug.cgi?format=multiple&id=356
:)

On 02/09/12 08:29, Attila Nagy wrote:
> 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
>
> _______________________________________________
> Unbound-users mailing list
> Unbound-users at unbound.net
> http://unbound.nlnetlabs.nl/mailman/listinfo/unbound-users