Auth ServFail not reproduceable (Hunting "Attempt to print an unset dnsname")

[klaus-nicat]

Hi! I have the following setup:

Customer-NS --AXFR--> MY-NS1 --AXFR--> MY-NS2

Customer-NS: PowerDNS, unknown Version
MY-NS1: PowerDNS 4.8.0, gpgsql backend
MY-NS2: PowerDNS 4.8.0, gpgsql backend, same config as MY-NS1

The Zone is preSigned (NSEC) and not RFC konform: it has a wildcard record with CNAME and A, ie:

*.example.com CNAME some.other.domain.not.hosted.on.this.powerdns
*.example.com A 192.168.0.1

dig @my-ns1 www.example.com returns both, the CNAME and A record. dig @my-ns1 www.example.com +dnssec returns ServFail: Exception building answer packet for www.example.com/A (Attempt to print an unset dnsname). dig @my-ns1 www.example.com +dnssec AAAA works and only returns the CNAME record.

I know the zone is not RFC conform. Nevertheless I want to find the buggy? code in PowerDNS that triggers the "Attempt to print an unset dnsname".

But the weird thing is, that if I query dig www.example.com +dnssec on Customer-NS or MY-NS2 it does not trigger an exception.

I have AXFRed out the zone from all 3 NS, they are identical. I have compared the domains, domainmetadata and records table on MY-NS1 and MY-NS2 and they are totall identical. On MY-NS1 and MY-NS2 all caches are deactivated.

I have no more idea what could be the problem that the query throws an exception only on one of the servers. Do you have any hints how to debug this? Thanks
Klaus

[aj-gh]

My first question would have been if the auth configs are identical, but then I noticed you already confirmed that, same for that entry in the domains table.
I wonder if it might have anything to do with record order in the database when pdns does a lookup on that specific entry?

[klaus-nicat]

I have enabled DLOG and put plenty of DLOGs in the code. AFAIS it goes this way:

packethandler.cc: PacketHandler::addNSEC()
  --> d_sd.db->getBeforeAndAfterNames(d_sd.domain_id, d_sd.qname, target, before, after);

dnsbackend.cc: dnsbackend.cc(...)
  --> bool ret = this->getBeforeAndAfterNamesAbsolute(id, qname.makeRelative(zonename).makeLowerCase(), unhashed, before, after);

gsqlbackend.cc: GSQLBackend::getBeforeAndAfterNamesAbsolute(...)
    d_afterOrderQuery_stmt->
      bind("ordername", qname.labelReverse().toString(" ", false))->
      bind("domain_id", id)->
      execute();
--> the toString(...) causes the exception.

Any ideas where I can look for an error? Hence the exception happens before the gpgsql-get-order-after-query.

Maybe, as Andreas said, it may be caused by the order of the records returned from DB, ie if the A or CNAME is returned first?

Here is debuglog (with some DLOGs added by me)

Received a packet 56 bytes long from 127.0.0.1
backend: 0, qname: www.example.com
lookup: www.example.com
Query 140082237460256: Statement: SELECT content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM records WHERE disabled=false and type=$1 and name=$2
Query 140082237460256: Parameters: $1 = 'SOA', $2 = 'www.example.com'
Query 140082237460256: 679 us to execute
Query 140082237460256: 702 us total to last row
no match for: www.example.com
backend: 0, qname: example.com
lookup: example.com
Query 140082237460256: Statement: SELECT content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM records WHERE disabled=false and type=$1 and name=$2
Query 140082237460256: Parameters: $1 = 'SOA', $2 = 'example.com'
Query 140082237460256: 155 us to execute
Query 140082237460256: 195 us total to last row
got: example.com
found: example.com
We have authority, zone='example.com', id=38254756
Query 140082237472208: Statement: select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name=$1
Query 140082237472208: Parameters: $1 = 'example.com'
Query 140082237472208: 3461 us to execute
Query 140082237472208: 3494 us total to last row
Checking for referrals first, unless this is a DS query
UeberBackend received question for NS of www.example.com
Query 140082237460576: Statement: SELECT content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM records WHERE disabled=false and type=$1 and name=$2 and domain_id=$3
Query 140082237460576: Parameters: $1 = 'NS', $2 = 'www.example.com', $3 = '38254756'
Query 140082237460576: 115 us to execute
Ueber get() was called for a NS record
Query 140082237460576: 146 us total to last row
UeberBackend reached end of backends
Got no referrals, trying ANY
Query 140082237472208: Statement: select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name=$1
Query 140082237472208: Parameters: $1 = 'example.com'
Query 140082237472208: 120 us to execute
Query 140082237472208: 132 us total to last row
UeberBackend received question for ANY of www.example.com
Query 140082237460928: Statement: SELECT content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM records WHERE disabled=false and name=$1 and domain_id=$2
Query 140082237460928: Parameters: $1 = 'www.example.com', $2 = '38254756'
Query 140082237460928: 93 us to execute
Ueber get() was called for a ANY record
Query 140082237460928: 148 us total to last row
UeberBackend reached end of backends
After first ANY query for 'www.example.com', id=38254756: weDone=0, weHaveUnauth=0, weRedirected=0, haveAlias='(empty)'
Found nothing in the by-name ANY, but let's try wildcards..
Query 140082237472208: Statement: select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name=$1
Query 140082237472208: Parameters: $1 = 'example.com'
Query 140082237472208: 152 us to execute
Query 140082237472208: 168 us total to last row
UeberBackend received question for ANY of *.example.com
Query 140082237460928: Statement: SELECT content,ttl,prio,type,domain_id,disabled::int,name,auth::int FROM records WHERE disabled=false and name=$1 and domain_id=$2
Query 140082237460928: Parameters: $1 = '*.example.com', $2 = '38254756'
Query 140082237460928: 122 us to execute
Ueber get() was called for a ANY record
Found an answering backend - will not try another one
Ueber get() was called for a ANY record
Found an answering backend - will not try another one
Ueber get() was called for a ANY record
Found an answering backend - will not try another one
Ueber get() was called for a ANY record
Found an answering backend - will not try another one
Ueber get() was called for a ANY record
Found an answering backend - will not try another one
Ueber get() was called for a ANY record
Query 140082237460928: 274 us total to last row
UeberBackend reached end of backends
Query 140082237472208: Statement: select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name=$1
Query 140082237472208: Parameters: $1 = 'example.com'
Query 140082237472208: 107 us to execute
Query 140082237472208: 122 us total to last row
addNSEC() mode=3 auth=example.com target=hosting-1b.foobar-ws.nl wildcard=*.example.com
before Nullptr
before DNSName
before getBeforeAndAfterNames
DNSBackend::getBeforeAndAfterNames before getBeforeAndAfterNamesAbsolute
GSQLBackend GSQLBackend::getBeforeAndAfterNamesAbsolute b
GSQLBackend GSQLBackend::getBeforeAndAfterNamesAbsolute 1
GSQLBackend GSQLBackend::getBeforeAndAfterNamesAbsolute 2
GSQLBackend GSQLBackend::getBeforeAndAfterNamesAbsolute 3
GSQLBackend GSQLBackend::getBeforeAndAfterNamesAbsolute 4
Exception building answer packet for www.example.com/A (Attempt to print an unset dnsname) sending out servfail
Sending a packet to 127.0.0.1:35928 (44 octets)

[rgacogne]

addNSEC() mode=3 auth=example.com target=hosting-1b.foobar-ws.nl wildcard=*.example.com

this does not look good. In DNSBackend::getBeforeAndAfterNames() we do qname.makeRelative(zonename).makeLowerCase() where qname is hosting-1b.foobar-ws.nl and zonename is example.com. Since qname does not belong to zonename, we will end up with an empty DNSName, which will indeed trigger the message Attempt to print an unset dnsname when we call toString(). Now of course the question is how we end up looking for a NSEC for a name that doesn't belong to the zone, assuming that this is not a mistake while redacting the output.

[klaus-nicat]

I managed to reproduce the issue and created the bug report #13561. Thanks for the feedback which helped me tracking down the issue.