"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
[email protected]
http://unbound.nlnetlabs.nl/mailman/listinfo/unbound-users
_______________________________________________
Unbound-users mailing list
[email protected]
http://unbound.nlnetlabs.nl/mailman/listinfo/unbound-users
