[Unbound-users] Can't resolve m.facebook.com
Attila Nagy
bra at fsn.hu
Thu Feb 9 07:49:37 UTC 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
More information about the Unbound-users
mailing list