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. A IN>: exceeded the maximum nameserver nxdomains
unbound[16750:0] error: SERVFAIL <dcp.dc1.philips.com. A IN>: all servers for this domain failed, at zone philips.com.
What i have looked so far:
- Infra cache is showing nameservers for this domain are not blocklisted
- 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
- 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