Intermittent SERVFAIL in unbound 1.10.1
Mike
intellivester at gmail.com
Mon Jul 13 01:06:36 UTC 2020
Hi,
I'm getting intermittent SERVFAILs when resolving domains under philips.com
(dcp.dc1.philips.com A , amplight.philips.com. MX, etc...) using unbound
1.10.1. When the issue occurs it seems to be consistent for several
minutes and eventually it resolves fine. I have done some troubleshooting
and i don't know if it is an unbound bug or an issue with the configuration
of this particular nameserver that triggers this behavior within unbound.
Here are my findings so far can someone help assist on what may be going
on?
Troubleshooting details:
Seeing the following message in unbound logs which seems to imply that it
had issues talking to auth nameservers for dcp.dc1.philips.com.
*unbound[16750:a] error: SERVFAIL <dcp.dc1.philips.com
<http://dcp.dc1.philips.com>. A IN>: exceeded the maximum nameserver
nxdomainsunbound[16750:0] error: SERVFAIL <dcp.dc1.philips.com
<http://dcp.dc1.philips.com>. A IN>: all servers for this domain failed, at
zone philips.com <http://philips.com>.*
What i have looked so far:
1. Infra cache is showing nameservers for this domain are not blocklisted
2. I monitored the delegation for several hours, to see if nxdomain,
servfail, nodata is returned for the nameservers intermittently but i
couldn't find anything
3. Tried to load a dump of infra cache + msg cache of when the issue
happens into a fresh unbound process but couldn't reproduce the servfail
behavior
When the issue happens i see the following content in the infra cache via
nslookup. One observation is that when AAAA records expire from infra cache
it starts resolving the domain again.
lookup dcp.dc1.philips.com
The following name servers are used for lookup of dcp.dc1.philips.com.
;rrset 1967 3 0 7 0
philips.com. 1967 IN NS ns3.ext.philips.com.
philips.com. 1967 IN NS ns2.ext.philips.com.
philips.com. 1967 IN NS ns1.ext.philips.com.
;rrset 1967 1 0 3 0
ns1.ext.philips.com. 1967 IN AAAA 2a01:ce89:8001:0:57:67:40:20
;rrset 1967 1 0 3 0
ns2.ext.philips.com. 1967 IN AAAA 2a01:ce95:4001:100:57:77:21:76
;rrset 1967 1 0 3 0
ns3.ext.philips.com. 1967 IN AAAA 2a01:ce9d:1:0:57:73:36:68
Delegation with 3 names, of which 3 can be examined to query further
addresses.
It provides 3 IP addresses.
2a01:ce9d:1:0:57:73:36:68 not in infra cache.
2a01:ce95:4001:100:57:77:21:76 not in infra cache.
2a01:ce89:8001:0:57:67:40:20 not in infra cache.
unbound verbose log shows that it may be running into cycles/loops. The
last resort processing doesn't seem to consult the nameservers for "com"
but it seems to be stuck looping around the philips nameservers hence
running out of targets.
unbound[10234:7] info: 10.200.194.144 dcp.dc1.philips.com. A IN
unbound[10234:7] debug: answer from the cache failed
unbound[10234:7] debug: udp request from ip4 10.200.194.144 port 32786 (len
16)
unbound[10234:7] debug: mesh_run: start
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_state_initial event:module_event_new
unbound[10234:7] debug: process_request: new external request event
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE
unbound[10234:7] info: resolving dcp.dc1.philips.com. A IN
unbound[10234:7] debug: request has dependency depth of 0
unbound[10234:7] debug: cache delegation returns delegpt
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 2)
unbound[10234:7] info: resolving (init part 2): dcp.dc1.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 3)
unbound[10234:7] info: resolving (init part 3): dcp.dc1.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: dcp.dc1.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: attempt to get extra 3 targets
unbound[10234:7] info: new target ns3.ext.philips.com. A IN
unbound[10234:7] info: new target ns2.ext.philips.com. A IN
unbound[10234:7] info: new target ns1.ext.philips.com. A IN
unbound[10234:7] debug: no current targets -- waiting for 3 targets to
resolve.
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_wait_subquery
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_state_initial event:module_event_pass
unbound[10234:7] info: iterator operate: query ns2.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE
unbound[10234:7] info: resolving ns2.ext.philips.com. A IN
unbound[10234:7] debug: request has dependency depth of 1
unbound[10234:7] debug: cache delegation returns delegpt
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 2)
unbound[10234:7] info: resolving (init part 2): ns2.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 3)
unbound[10234:7] info: resolving (init part 3): ns2.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: ns2.ext.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: attempt to get extra 2 targets
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns2.ext.philips.com. A IN
unbound[10234:7] info: new target ns3.ext.philips.com. A IN
unbound[10234:7] info: new target ns1.ext.philips.com. A IN
unbound[10234:7] debug: no current targets -- waiting for 2 targets to
resolve.
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_wait_subquery
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_state_initial event:module_event_pass
unbound[10234:7] info: iterator operate: query ns3.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE
unbound[10234:7] info: resolving ns3.ext.philips.com. A IN
unbound[10234:7] debug: request has dependency depth of 1
unbound[10234:7] debug: cache delegation returns delegpt
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 2)
unbound[10234:7] info: resolving (init part 2): ns3.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 3)
unbound[10234:7] info: resolving (init part 3): ns3.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: ns3.ext.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: attempt to get extra 2 targets
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns3.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns2.ext.philips.com. A IN
unbound[10234:7] info: new target ns1.ext.philips.com. A IN
unbound[10234:7] debug: no current targets -- waiting for 1 targets to
resolve.
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_wait_subquery
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_state_initial event:module_event_pass
unbound[10234:7] info: iterator operate: query ns1.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE
unbound[10234:7] info: resolving ns1.ext.philips.com. A IN
unbound[10234:7] debug: request has dependency depth of 1
unbound[10234:7] debug: cache delegation returns delegpt
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 2)
unbound[10234:7] info: resolving (init part 2): ns1.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state INIT REQUEST
STATE (stage 3)
unbound[10234:7] info: resolving (init part 3): ns1.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: ns1.ext.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (3 missing),
3 addrs (0 result, 3 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. AAAA
unbound[10234:7] info: ns2.ext.philips.com. AAAA
unbound[10234:7] info: ns1.ext.philips.com. AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: attempt to get extra 2 targets
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns3.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns2.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
(harden-glue: no may fix some of the cycles) ns1.ext.philips.com. A IN
unbound[10234:7] debug: No more query targets, attempting last resort
unbound[10234:7] info: found parent-side NS in cache philips.com. NS IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found parent-side ns3.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns2.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns1.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns3.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns2.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns1.ext.philips.com. A IN
unbound[10234:7] debug: out of query targets -- returning SERVFAIL
unbound[10234:7] debug: store error response in message cache
unbound[10234:7] debug: return error response SERVFAIL
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_finished
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
unbound[10234:7] info: iterator operate: query ns3.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: ns3.ext.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (0 missing),
3 addrs (3 result, 0 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. * AAAA
unbound[10234:7] info: ns2.ext.philips.com. * AAAA
unbound[10234:7] info: ns1.ext.philips.com. * A AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: No more query targets, attempting last resort
unbound[10234:7] info: found parent-side NS in cache philips.com. NS IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found parent-side ns3.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns2.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns1.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns3.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns2.ext.philips.com. A IN
unbound[10234:7] debug: out of query targets -- returning SERVFAIL
unbound[10234:7] debug: store error response in message cache
unbound[10234:7] debug: return error response SERVFAIL
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_finished
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
unbound[10234:7] info: iterator operate: query dcp.dc1.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: dcp.dc1.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 1,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (0 missing),
3 addrs (3 result, 0 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. * A AAAA
unbound[10234:7] info: ns2.ext.philips.com. * AAAA
unbound[10234:7] info: ns1.ext.philips.com. * A AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: no current targets -- waiting for 1 targets to
resolve.
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_wait_subquery
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
unbound[10234:7] info: iterator operate: query ns2.ext.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: ns2.ext.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] info: DelegationPoint<philips.com.>: 3 names (0 missing),
3 addrs (3 result, 0 avail) cacheNS
unbound[10234:7] info: ns3.ext.philips.com. * A AAAA
unbound[10234:7] info: ns2.ext.philips.com. * AAAA
unbound[10234:7] info: ns1.ext.philips.com. * A AAAA
unbound[10234:7] debug: ip6 2a01:ce89:8001:0:57:67:40:20 port 53 (len 28)
unbound[10234:7] debug: ip6 2a01:ce95:4001:100:57:77:21:76 port 53 (len
28)
unbound[10234:7] debug: ip6 2a01:ce9d:1:0:57:73:36:68 port 53 (len 28)
unbound[10234:7] debug: No more query targets, attempting last resort
unbound[10234:7] info: found parent-side NS in cache philips.com. NS IN
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] info: found parent-side ns3.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns2.ext.philips.com. A IN
unbound[10234:7] info: found parent-side ns1.ext.philips.com. A IN
unbound[10234:7] info: skipping target due to dependency cycle
ns2.ext.philips.com. A IN
unbound[10234:7] debug: out of query targets -- returning SERVFAIL
unbound[10234:7] debug: store error response in message cache
unbound[10234:7] debug: return error response SERVFAIL
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_finished
unbound[10234:7] info: found in cache ns3.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns2.ext.philips.com. AAAA IN
unbound[10234:7] info: found in cache ns1.ext.philips.com. AAAA IN
unbound[10234:7] debug: iterator[module 0] operate:
extstate:module_wait_subquery event:module_event_pass
unbound[10234:7] info: iterator operate: query dcp.dc1.philips.com. A IN
unbound[10234:7] debug: iter_handle processing q with state QUERY TARGETS
STATE
unbound[10234:7] info: processQueryTargets: dcp.dc1.philips.com. A IN
unbound[10234:7] debug: processQueryTargets: targetqueries 0,
currentqueries 0 sentcount 0
unbound[10234:7] debug: request has exceeded the maximum number of
nxdomain nameserver lookups with 6
unbound[10234:7] debug: return error response SERVFAIL
unbound[10234:7] debug: mesh_run: iterator module exit state is
module_finished
unbound[10234:7] error: SERVFAIL <dcp.dc1.philips.com. A IN>: exceeded the
maximum nameserver nxdomains
unbound[10234:7] debug: query took 0.000000 sec
Thanks,
Mike
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20200712/ff1f55a5/attachment-0001.htm>
More information about the Unbound-users
mailing list