[Pdns-users] Problems with PowerDNS and specific Domain

[Markus Ehrlicher]

Hello together,

since a few days, we have massive problems with DNS-lookup for a specific domain (ws.igspn.com) from our two recursors (PDNS-Recursor 4.8.2 on Ubuntu 18.04LTS). On my first investigation, I thought that bad latency to the responsible nameservers is the problem, but if I do a forward-zones-recurse to Google (forward-zones-recurse=igspn.com=8.8.8.8), everything works like a charm. I traced both lookups, but I can't find a clue, what could be wrong on our side. Can someone test from another location, to rule out that it is a PowerDNS problem? Any other suggestions?

Normal Recursion with our PDNS:

Feb  2 08:33:36 ns1 pdns_recursor[916]: msg="Question" subsystem="syncres" level="0" prio="Info" tid="2" ts="1675323216.262" ecs="" mtid="2106445" proto="udp" qname="ws.igspn.com" qtype="A" remote="217.119.214.16:37329"
Feb  2 08:33:39 ns1 pdns_recursor[916]: : no TA found for 'ws.igspn.com' among 1
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=(empty): doResolve
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Wants DNSSEC processing, auth data in query for A
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Recursion not requested for 'ws.igspn.com|A', peeking at auth/forward zones
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=(empty): Step0 Not cached
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: no valid/useful NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: no valid/useful NS in cache for 'igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'e.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'b.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'a.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'd.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'i.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'f.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'j.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'k.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'c.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'g.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'h.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'l.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'com' -> 'm.gtld-servers.net'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: We have NS in cache for 'com' (flawedNSSet=0)
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=(empty): Step1 Ancestor from cache is com
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=igspn.com: Step2 New child
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=igspn.com: Step4 Resolve A for child
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=igspn.com: Step4 Resolve A result is No Error/0/2
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=igspn.com: Delegation seen, continue at step 1
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: no valid/useful NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'igspn.com' -> 'ns1.namecity.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'igspn.com' -> 'ns2.namecity.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: We have NS in cache for 'igspn.com' (flawedNSSet=0)
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=igspn.com: Step1 Ancestor from cache is igspn.com
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=ws.igspn.com: Step2 New child
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=ws.igspn.com: Step3 Going to do final resolve
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Wants DNSSEC processing, auth data in query for A
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: No cache hit for 'ws.igspn.com|A', trying to find an appropriate NS record
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: no valid/useful NS in cache for 'ws.igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Checking if we have NS in cache for 'igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'igspn.com' -> 'ns1.namecity.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: NS (with ip, or non-glue) in cache for 'igspn.com' -> 'ns2.namecity.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: within bailiwick: 0, not in cache / did not look at cache
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: We have NS in cache for 'igspn.com' (flawedNSSet=0)
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Cache consultations done, have 2 NS to contact
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com.: Nameservers: ns1.namecity.com(261.61ms), ns2.namecity.com(286.99ms)
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Trying to resolve NS 'ns1.namecity.com' (1/2)
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Resolved 'igspn.com' NS ns1.namecity.com to: 62.128.193.35
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Trying IP 62.128.193.35:53, asking 'ws.igspn.com|A'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: timeout resolving after 1574.81msec
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Trying to resolve NS 'ns2.namecity.com' (2/2)
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Resolved 'igspn.com' NS ns2.namecity.com to: 84.22.161.171
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Trying IP 84.22.161.171:53, asking 'ws.igspn.com|A'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: timeout resolving after 1514.68msec
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: Failed to resolve via any of the 2 offered NS at level 'igspn.com'
Feb  2 08:33:39 ns1 pdns_recursor[916]: ws.igspn.com: failed (res=-1)
Feb  2 08:33:39 ns1 pdns_recursor[916]: QM ws.igspn.com.|A child=ws.igspn.com: Step3 Final resolve: Server Failure/0
Feb  2 08:33:39 ns1 pdns_recursor[916]: msg="Answer" subsystem="syncres" level="0" prio="Info" tid="2" ts="1675323219.384" additional="0" answers="0" dotout="0" ecs="" mtid="2106445" netms="3109.711000" outqueries="3" proto="udp" qname=
ws.igspn.com" qtype="A" rcode="2" rd="1" remote="217.119.214.16:37329" tcpout="0" throttled="0" timeouts="2" totms="3111.410000" validationState="Indeterminate"

Recursion over Google-DNS (forward-zones-recurse=igspn.com=8.8.8.8):

Feb  2 08:38:23 ns1 pdns_recursor[30345]: msg="Question" subsystem="syncres" level="0" prio="Info" tid="3" ts="1675323503.503" ecs="" mtid="1829" proto="udp" qname="ws.igspn.com" qtype="A" remote="217.119.214.16:44096"
Feb  2 08:38:23 ns1 pdns_recursor[30345]: : no TA found for 'ws.igspn.com' among 1
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Wants DNSSEC processing, auth data in query for A
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: No cache hit for 'ws.igspn.com|A', trying to find an appropriate NS record
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Cache consultations done, have 1 NS to contact
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Domain has hardcoded nameserver
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com.: Nameservers: +8.8.8.8:53(8.44ms)
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Resolved 'igspn.com' NS (empty) to: 8.8.8.8
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Trying IP 8.8.8.8:53, asking 'ws.igspn.com|A'
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: Got 2 answers from (empty) (8.8.8.8), rcode=0 (No Error), aa=0, in 22ms
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: accept answer 'ws.igspn.com|A|210.118.78.162' from 'igspn.com' nameservers? ttl=7200, place=1 YES! - This answer was received from a server we forward to.
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: OPT answer '.' from 'igspn.com' nameservers
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: determining status after receiving this packet
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: answer is in: resolved to '210.118.78.162|A'
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: status=got results, this level of recursion done
Feb  2 08:38:23 ns1 pdns_recursor[30345]: ws.igspn.com: validation status is Indeterminate
Feb  2 08:38:23 ns1 pdns_recursor[30345]: msg="Answer" subsystem="syncres" level="0" prio="Info" tid="3" ts="1675323503.531" additional="0" answers="1" dotout="0" ecs="" mtid="1829" netms="22.486000" outqueries="1" proto="udp" qname="ws.igspn.com" qtype="A" rcode="0" rd="1" remote="217.119.214.16:44096" tcpout="0" throttled="0" timeouts="0" totms="23.312000" validationState="Indeterminate"

Thanks and best regards,
Markus