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
