From: Kees Monshouwer <mind04@monshouwer.org>
Date: Mon, 23 Nov 2020 13:03:59 +0000 (+0100)
Subject: auth: add zone and primary to all axfr logging
X-Git-Tag: auth-4.5.0-alpha0^2~1
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=efe7948eea6696ccd408ff2a1f4d850e3866fafb;p=thirdparty%2Fpdns.git

auth: add zone and primary to all axfr logging
---

diff --git a/pdns/slavecommunicator.cc b/pdns/slavecommunicator.cc
index 31460c19b7..b3f47248f3 100644
--- a/pdns/slavecommunicator.cc
+++ b/pdns/slavecommunicator.cc
@@ -83,6 +83,8 @@ struct ZoneStatus
 void CommunicatorClass::ixfrSuck(const DNSName &domain, const TSIGTriplet& tt, const ComboAddress& laddr, const ComboAddress& remote, unique_ptr<AuthLua4>& pdl,
                                  ZoneStatus& zs, vector<DNSRecord>* axfr)
 {
+  string logPrefix="IXFR-in zone '"+domain.toLogString()+"', primary '"+remote.toString()+"', ";
+
   UeberBackend B; // fresh UeberBackend
 
   DomainInfo di;
@@ -95,9 +97,9 @@ void CommunicatorClass::ixfrSuck(const DNSName &domain, const TSIGTriplet& tt, c
     // this checks three error conditions, and sets wrongDomainKind if we hit the third & had an error
     if(!B.getDomainInfo(domain, di) || !di.backend || (wrongDomainKind = true, di.kind != DomainInfo::Slave)) { // di.backend and B are mostly identical
       if(wrongDomainKind)
-        g_log<<Logger::Warning<<"Can't determine backend for domain '"<<domain<<"', not configured as slave"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"can't determine backend, not configured as slave"<<endl;
       else
-        g_log<<Logger::Warning<<"Can't determine backend for domain '"<<domain<<"'"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"can't determine backend"<<endl;
       return;
     }
 
@@ -179,11 +181,11 @@ void CommunicatorClass::ixfrSuck(const DNSName &domain, const TSIGTriplet& tt, c
     }
   }
   catch(std::exception& p) {
-    g_log<<Logger::Error<<"Got exception during IXFR: "<<p.what()<<endl;
+    g_log<<Logger::Error<<logPrefix<<"got exception (std::exception): "<<p.what()<<endl;
     throw;
   }
   catch(PDNSException& p) {
-    g_log<<Logger::Error<<"Got exception during IXFR: "<<p.reason<<endl;
+    g_log<<Logger::Error<<logPrefix<<"got exception (PDNSException): "<<p.reason<<endl;
     throw;
   }  
 }
@@ -248,9 +250,10 @@ static vector<DNSResourceRecord> doAxfr(const ComboAddress& raddr, const DNSName
   bool first=true;
   bool firstNSEC3{true};
   bool soa_received {false};
+  string logPrefix="AXFR-in zone '"+domain.toLogString()+"', primary '"+raddr.toString()+"', ";
   while(retriever.getChunk(recs, nullptr, axfr_timeout)) {
     if(first) {
-      g_log<<Logger::Notice<<"AXFR started for '"<<domain<<"'"<<endl;
+      g_log<<Logger::Notice<<logPrefix<<"retrieval started"<<endl;
       first=false;
     }
 
@@ -260,7 +263,7 @@ static vector<DNSResourceRecord> doAxfr(const ComboAddress& raddr, const DNSName
         continue;
 
       if(!i->qname.isPartOf(domain)) {
-        g_log<<Logger::Warning<<"Remote "<<raddr.toStringWithPort()<<" tried to sneak in out-of-zone data '"<<i->qname<<"'|"<<i->qtype.getName()<<" during AXFR of zone '"<<domain<<"', ignoring"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"primary tried to sneak in out-of-zone data '"<<i->qname<<"'|"<<i->qtype.getName()<<", ignoring"<<endl;
         continue;
       }
 
@@ -271,7 +274,7 @@ static vector<DNSResourceRecord> doAxfr(const ComboAddress& raddr, const DNSName
 
       for(DNSResourceRecord& rr :  out) {
         if(!rr.qname.isPartOf(domain)) {
-          g_log<<Logger::Error<<"Lua axfrfilter() filter tried to sneak in out-of-zone data '"<<i->qname<<"'|"<<i->qtype.getName()<<" during AXFR of zone '"<<domain<<"', ignoring"<<endl;
+          g_log<<Logger::Error<<logPrefix<<"axfrfilter() filter tried to sneak in out-of-zone data '"<<i->qname<<"'|"<<i->qtype.getName()<<", ignoring"<<endl;
           continue;
         }
         if(!processRecordForZS(domain, firstNSEC3, rr, zs))
@@ -305,7 +308,9 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
   }
   RemoveSentinel rs(domain, this); // this removes us from d_inprogress when we go out of scope
 
-  g_log<<Logger::Notice<<"Initiating transfer of '"<<domain<<"' from remote '"<<remote<<"'"<<endl;
+  string logPrefix="XFR-in zone: '"+domain.toLogString()+"', primary: '"+remote.toString()+"', ";
+
+  g_log<<Logger::Notice<<logPrefix<<"initiating transfer"<<endl;
   UeberBackend B; // fresh UeberBackend
 
   DomainInfo di;
@@ -317,9 +322,9 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
     // this checks three error conditions & sets wrongDomainKind if we hit the third
     if(!B.getDomainInfo(domain, di) || !di.backend || (wrongDomainKind = true, !force && di.kind != DomainInfo::Slave)) { // di.backend and B are mostly identical
       if(wrongDomainKind)
-        g_log<<Logger::Warning<<"Can't determine backend for domain '"<<domain<<"', not configured as slave"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"can't determine backend, not configured as slave"<<endl;
       else
-        g_log<<Logger::Warning<<"Can't determine backend for domain '"<<domain<<"'"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"can't determine backend"<<endl;
       return;
     }
     ZoneStatus zs;
@@ -330,11 +335,11 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
       string tsigsecret64;
       if(B.getTSIGKey(tt.name, &tt.algo, &tsigsecret64)) {
         if(B64Decode(tsigsecret64, tt.secret)) {
-          g_log<<Logger::Error<<"Unable to Base-64 decode TSIG key '"<<tt.name<<"' for domain '"<<domain<<"' not found"<<endl;
+          g_log<<Logger::Error<<logPrefix<<"unable to Base-64 decode TSIG key '"<<tt.name<<"' or zone not found"<<endl;
           return;
         }
       } else {
-        g_log<<Logger::Warning<<"TSIG key '"<<tt.name<<"' for domain '"<<domain<<"' not found"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"TSIG key '"<<tt.name<<"' for zone not found"<<endl;
         return;
       }
     }
@@ -354,10 +359,10 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
       try {
         pdl = make_unique<AuthLua4>();
         pdl->loadFile(script);
-        g_log<<Logger::Info<<"Loaded Lua script '"<<script<<"' to edit the incoming AXFR of '"<<domain<<"'"<<endl;
+        g_log<<Logger::Info<<logPrefix<<"loaded Lua script '"<<script<<"'"<<endl;
       }
       catch(std::exception& e) {
-        g_log<<Logger::Error<<"Failed to load Lua editing script '"<<script<<"' for incoming AXFR of '"<<domain<<"': "<<e.what()<<endl;
+        g_log<<Logger::Error<<logPrefix<<"failed to load Lua script '"<<script<<"': "<<e.what()<<endl;
         return;
       }
     }
@@ -368,17 +373,17 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
     if(B.getDomainMetadata(domain, "AXFR-SOURCE", localaddr) && !localaddr.empty()) {
       try {
         laddr = ComboAddress(localaddr[0]);
-        g_log<<Logger::Info<<"AXFR source for domain '"<<domain<<"' set to "<<localaddr[0]<<endl;
+        g_log<<Logger::Info<<logPrefix<<"xfr source set to "<<localaddr[0]<<endl;
       }
       catch(std::exception& e) {
-        g_log<<Logger::Error<<"Failed to load AXFR source '"<<localaddr[0]<<"' for incoming AXFR of '"<<domain<<"': "<<e.what()<<endl;
+        g_log<<Logger::Error<<logPrefix<<"failed to set xfr source '"<<localaddr[0]<<"': "<<e.what()<<endl;
         return;
       }
     } else {
       if (!pdns::isQueryLocalAddressFamilyEnabled(remote.sin4.sin_family)) {
         bool isV6 = remote.sin4.sin_family == AF_INET6;
-        g_log<<Logger::Warning<<"Unable to AXFR, destination address is "<<remote<<" (IPv"<< (isV6 ? "6" : "4") <<
-          ", but that address family is not enabled for outgoing traffic (query-local-address)"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"unable to xfr, address family (IPv"<< (isV6 ? "6" : "4") <<
+          " is not enabled for outgoing traffic (query-local-address)"<<endl;
         return;
       }
       laddr = pdns::getQueryLocalAddress(remote.sin4.sin_family, 0);
@@ -405,11 +410,13 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
       vector<string> meta;
       B.getDomainMetadata(domain, "IXFR", meta);
       if(!meta.empty() && meta[0]=="1") {
+        logPrefix = "I" + logPrefix; // XFR -> IXFR
         vector<DNSRecord> axfr;
-        g_log<<Logger::Notice<<"Starting IXFR of '"<<domain<<"' from remote "<<remote<<endl;
+        g_log<<Logger::Notice<<logPrefix<<"starting IXFR"<<endl;
         ixfrSuck(domain, tt, laddr, remote, pdl, zs, &axfr);
         if(!axfr.empty()) {
-          g_log<<Logger::Notice<<"IXFR of '"<<domain<<"' from remote '"<<remote<<"' turned into an AXFR"<<endl;
+          g_log<<Logger::Notice<<logPrefix<<"IXFR turned into an AXFR"<<endl;
+          logPrefix[0]='A'; // IXFR -> AXFR
           bool firstNSEC3=true;
           rrs.reserve(axfr.size());
           for(const auto& dr : axfr) {
@@ -426,7 +433,7 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
           }
         }
         else {
-          g_log<<Logger::Warning<<"Done with IXFR of '"<<domain<<"' from remote '"<<remote<<"', got "<<zs.numDeltas<<" delta"<<addS(zs.numDeltas)<<", serial now "<<zs.soa_serial<<endl;
+          g_log<<Logger::Warning<<logPrefix<<"got "<<zs.numDeltas<<" delta"<<addS(zs.numDeltas)<<", zone committed with serial "<<zs.soa_serial<<endl;
           purgeAuthCaches(domain.toString()+"$");
           return;
         }
@@ -434,11 +441,12 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
     }
 
     if(rrs.empty()) {
-      g_log<<Logger::Notice<<"Starting AXFR of '"<<domain<<"' from remote "<<remote<<endl;
+      g_log<<Logger::Notice<<logPrefix<<"starting AXFR"<<endl;
       rrs = doAxfr(remote, domain, tt, laddr, pdl, zs);
-      g_log<<Logger::Notice<<"AXFR of '"<<domain<<"' from remote "<<remote<<" done"<<endl;
+      logPrefix = "A" + logPrefix; // XFR -> AXFR
+      g_log<<Logger::Notice<<logPrefix<<"retrieval finished"<<endl;
     }
- 
+
     if(zs.isNSEC3) {
       zs.ns3pr.d_flags = zs.optOutFlag ? 1 : 0;
     }
@@ -456,16 +464,16 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
 
     if(zs.isDnssecZone) {
       if(!zs.isNSEC3)
-        g_log<<Logger::Debug<<"Adding NSEC ordering information"<<endl;
+        g_log<<Logger::Debug<<logPrefix<<"adding NSEC ordering information"<<endl;
       else if(!zs.isNarrow)
-        g_log<<Logger::Debug<<"Adding NSEC3 hashed ordering information for '"<<domain<<"'"<<endl;
+        g_log<<Logger::Debug<<logPrefix<<"adding NSEC3 hashed ordering information"<<endl;
       else
-        g_log<<Logger::Debug<<"Erasing NSEC3 ordering since we are narrow, only setting 'auth' fields"<<endl;
+        g_log<<Logger::Debug<<logPrefix<<"zone is narrow, only setting 'auth' fields"<<endl;
     }
 
 
     transaction=di.backend->startTransaction(domain, zs.domain_id);
-    g_log<<Logger::Info<<"Backend transaction started for '"<<domain<<"' storage"<<endl;
+    g_log<<Logger::Info<<logPrefix<<"storage transaction started"<<endl;
 
     // update the presigned flag and NSEC3PARAM
     if (zs.isDnssecZone) {
@@ -552,7 +560,7 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
         }
 
         if(nonterm.size() > maxent) {
-          g_log<<Logger::Warning<<"AXFR zone "<<domain<<" has too many empty non terminals."<<endl;
+          g_log<<Logger::Warning<<logPrefix<<"zone has too many empty non terminals"<<endl;
           nonterm.clear();
           doent=false;
         }
@@ -596,7 +604,7 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
     di.backend->setFresh(zs.domain_id);
     purgeAuthCaches(domain.toString()+"$");
 
-    g_log<<Logger::Warning<<"AXFR done for '"<<domain<<"', zone committed with serial number "<<zs.soa_serial<<endl;
+    g_log<<Logger::Warning<<logPrefix<<"zone committed with serial "<<zs.soa_serial<<endl;
 
     // Send slave re-notifications
     bool doNotify;
@@ -612,23 +620,23 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
 
   }
   catch(DBException &re) {
-    g_log<<Logger::Error<<"Unable to feed record during incoming AXFR of '" << domain<<"': "<<re.reason<<endl;
+    g_log<<Logger::Error<<logPrefix<<"unable to feed record: "<<re.reason<<endl;
     if(di.backend && transaction) {
-      g_log<<Logger::Info<<"Aborting possible open transaction for domain '"<<domain<<"' AXFR"<<endl;
+      g_log<<Logger::Info<<logPrefix<<"aborting possible open transaction"<<endl;
       di.backend->abortTransaction();
     }
   }
   catch(const MOADNSException &mde) {
-    g_log<<Logger::Error<<"Unable to parse record during incoming AXFR of '"<<domain<<"' (MOADNSException): "<<mde.what()<<endl;
+    g_log<<Logger::Error<<logPrefix<<"unable to parse record (MOADNSException): "<<mde.what()<<endl;
     if(di.backend && transaction) {
-      g_log<<Logger::Info<<"Aborting possible open transaction for domain '"<<domain<<"' AXFR"<<endl;
+      g_log<<Logger::Info<<logPrefix<<"aborting possible open transaction"<<endl;
       di.backend->abortTransaction();
     }
   }
   catch(std::exception &re) {
-    g_log<<Logger::Error<<"Unable to parse record during incoming AXFR of '"<<domain<<"' (std::exception): "<<re.what()<<endl;
+    g_log<<Logger::Error<<logPrefix<<"unable to xfr zone (std::exception): "<<re.what()<<endl;
     if(di.backend && transaction) {
-      g_log<<Logger::Info<<"Aborting possible open transaction for domain '"<<domain<<"' AXFR"<<endl;
+      g_log<<Logger::Info<<logPrefix<<"aborting possible open transaction"<<endl;
       di.backend->abortTransaction();
     }
   }
@@ -645,17 +653,17 @@ void CommunicatorClass::suck(const DNSName &domain, const ComboAddress& remote,
         newCount = d_failedSlaveRefresh[domain].first + 1;
       time_t nextCheck = now + std::min(newCount * d_tickinterval, (uint64_t)::arg().asNum("default-ttl"));
       d_failedSlaveRefresh[domain] = {newCount, nextCheck};
-      g_log<<Logger::Warning<<"Unable to AXFR zone '"<<domain<<"' from remote '"<<remote<<"' (resolver): "<<re.reason<<" (This was the "<<(newCount == 1 ? "first" : std::to_string(newCount) + "th")<<" time. Excluding zone from slave-checks until "<<nextCheck<<")"<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"unable to xfr zone (ResolverException): "<<re.reason<<" (This was the "<<(newCount == 1 ? "first" : std::to_string(newCount) + "th")<<" time. Excluding zone from slave-checks until "<<nextCheck<<")"<<endl;
     }
     if(di.backend && transaction) {
-      g_log<<Logger::Info<<"Aborting possible open transaction for domain '"<<domain<<"' AXFR"<<endl;
+      g_log<<Logger::Info<<"aborting possible open transaction"<<endl;
       di.backend->abortTransaction();
     }
   }
   catch(PDNSException &ae) {
-    g_log<<Logger::Error<<"Unable to AXFR zone '"<<domain<<"' from remote '"<<remote<<"' (PDNSException): "<<ae.reason<<endl;
+    g_log<<Logger::Error<<logPrefix<<"unable to xfr zone (PDNSException): "<<ae.reason<<endl;
     if(di.backend && transaction) {
-      g_log<<Logger::Info<<"Aborting possible open transaction for domain '"<<domain<<"' AXFR"<<endl;
+      g_log<<Logger::Info<<logPrefix<<"aborting possible open transaction"<<endl;
       di.backend->abortTransaction();
     }
   }
diff --git a/pdns/tcpreceiver.cc b/pdns/tcpreceiver.cc
index 8b84ca49fb..609d5ef3c7 100644
--- a/pdns/tcpreceiver.cc
+++ b/pdns/tcpreceiver.cc
@@ -388,11 +388,13 @@ void TCPNameserver::doConnection(int fd)
 
 
 // call this method with s_plock held!
-bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q)
+bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q, bool isAXFR)
 {
   if(::arg().mustDo("disable-axfr"))
     return false;
 
+  string logPrefix=string(isAXFR ? "A" : "I")+"XFR-out zone '"+q->qdomain.toLogString()+"', client '"+q->getRemote().toStringWithPort()+"', ";
+
   if(q->d_havetsig) { // if you have one, it must be good
     TSIGRecordContent trc;
     DNSName keyname;
@@ -405,18 +407,18 @@ bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q)
 
     DNSSECKeeper dk(s_P->getBackend());
     if(!dk.TSIGGrantsAccess(q->qdomain, keyname)) {
-      g_log<<Logger::Warning<<"AXFR '"<<q->qdomain<<"' denied: key with name '"<<keyname<<"' and algorithm '"<<getTSIGAlgoName(q->d_tsig_algo)<<"' does not grant access to zone"<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"denied: key with name '"<<keyname<<"' and algorithm '"<<getTSIGAlgoName(q->d_tsig_algo)<<"' does not grant access"<<endl;
       return false;
     }
     else {
-      g_log<<Logger::Notice<<"AXFR of domain '"<<q->qdomain<<"' allowed: TSIG signed request with authorized key '"<<keyname<<"' and algorithm '"<<getTSIGAlgoName(q->d_tsig_algo)<<"'"<<endl;
+      g_log<<Logger::Notice<<logPrefix<<"allowed: TSIG signed request with authorized key '"<<keyname<<"' and algorithm '"<<getTSIGAlgoName(q->d_tsig_algo)<<"'"<<endl;
       return true;
     }
   }
   
   // cerr<<"checking allow-axfr-ips"<<endl;
   if(!(::arg()["allow-axfr-ips"].empty()) && d_ng.match( (ComboAddress *) &q->d_remote )) {
-    g_log<<Logger::Notice<<"AXFR of domain '"<<q->qdomain<<"' allowed: client IP "<<q->getRemote()<<" is in allow-axfr-ips"<<endl;
+    g_log<<Logger::Notice<<logPrefix<<"allowed: client IP is in allow-axfr-ips"<<endl;
     return true;
   }
 
@@ -447,7 +449,7 @@ bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q)
             if(*k == q->getRemote().toString())
             {
               // cerr<<"got AUTO-NS hit"<<endl;
-              g_log<<Logger::Notice<<"AXFR of domain '"<<q->qdomain<<"' allowed: client IP "<<q->getRemote()<<" is in NSset"<<endl;
+              g_log<<Logger::Notice<<logPrefix<<"allowed: client IP is in NSset"<<endl;
               return true;
             }
           }
@@ -458,7 +460,7 @@ bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q)
         Netmask nm = Netmask(*i);
         if(nm.match( (ComboAddress *) &q->d_remote ))
         {
-          g_log<<Logger::Notice<<"AXFR of domain '"<<q->qdomain<<"' allowed: client IP "<<q->getRemote()<<" is in per-domain ACL"<<endl;
+          g_log<<Logger::Notice<<logPrefix<<"allowed: client IP is in per-zone ACL"<<endl;
           // cerr<<"hit!"<<endl;
           return true;
         }
@@ -469,11 +471,11 @@ bool TCPNameserver::canDoAXFR(std::unique_ptr<DNSPacket>& q)
   extern CommunicatorClass Communicator;
 
   if(Communicator.justNotified(q->qdomain, q->getRemote().toString())) { // we just notified this ip
-    g_log<<Logger::Notice<<"Approved AXFR of '"<<q->qdomain<<"' from recently notified slave "<<q->getRemote()<<endl;
+    g_log<<Logger::Notice<<logPrefix<<"allowed: client IP is from recently notified secondary"<<endl;
     return true;
   }
 
-  g_log<<Logger::Warning<<"AXFR of domain '"<<q->qdomain<<"' denied: client IP "<<q->getRemote()<<" has no permission"<<endl;
+  g_log<<Logger::Warning<<logPrefix<<"denied: client IP has no permission"<<endl;
   return false;
 }
 
@@ -499,32 +501,34 @@ namespace {
 /** do the actual zone transfer. Return 0 in case of error, 1 in case of success */
 int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q, int outsock)
 {
+  string logPrefix="AXFR-out zone '"+target.toLogString()+"', client '"+q->getRemote().toStringWithPort()+"', ";
+
   std::unique_ptr<DNSPacket> outpacket= getFreshAXFRPacket(q);
   if(q->d_dnssecOk)
     outpacket->d_dnssecOk=true; // RFC 5936, 2.2.5 'SHOULD'
 
-  g_log<<Logger::Warning<<"AXFR of domain '"<<target<<"' initiated by "<<q->getRemote()<<endl;
+  g_log<<Logger::Warning<<logPrefix<<"transfer initiated"<<endl;
 
   // determine if zone exists and AXFR is allowed using existing backend before spawning a new backend.
   SOAData sd;
   {
     std::lock_guard<std::mutex> l(s_plock);
-    DLOG(g_log<<"Looking for SOA"<<endl);    // find domain_id via SOA and list complete domain. No SOA, no AXFR
+    DLOG(g_log<<logPrefix<<"looking for SOA"<<endl);    // find domain_id via SOA and list complete domain. No SOA, no AXFR
     if(!s_P) {
       g_log<<Logger::Warning<<"TCP server is without backend connections in doAXFR, launching"<<endl;
       s_P=make_unique<PacketHandler>();
     }
 
     // canDoAXFR does all the ACL checks, and has the if(disable-axfr) shortcut, call it first.
-    if (!canDoAXFR(q)) {
-      g_log<<Logger::Warning<<"AXFR of domain '"<<target<<"' failed: "<<q->getRemote()<<" may not request AXFR"<<endl;
+    if (!canDoAXFR(q, true)) {
+      g_log<<Logger::Warning<<logPrefix<<"failed: client may not request AXFR"<<endl;
       outpacket->setRcode(RCode::NotAuth);
       sendPacket(outpacket,outsock);
       return 0;
     }
 
     if(!s_P->getBackend()->getSOAUncached(target, sd)) {
-      g_log<<Logger::Warning<<"AXFR of domain '"<<target<<"' failed: not authoritative"<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"failed: not authoritative"<<endl;
       outpacket->setRcode(RCode::NotAuth);
       sendPacket(outpacket,outsock);
       return 0;
@@ -533,7 +537,7 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
 
   UeberBackend db;
   if(!db.getSOAUncached(target, sd)) {
-    g_log<<Logger::Warning<<"AXFR of domain '"<<target<<"' failed: not authoritative in second instance"<<endl;
+    g_log<<Logger::Warning<<logPrefix<<"failed: not authoritative in second instance"<<endl;
     outpacket->setRcode(RCode::NotAuth);
     sendPacket(outpacket,outsock);
     return 0;
@@ -550,7 +554,7 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
   if(securedZone && dk.getNSEC3PARAM(target, &ns3pr, &narrow)) {
     NSEC3Zone=true;
     if(narrow) {
-      g_log<<Logger::Warning<<"Not doing AXFR of an NSEC3 narrow zone '"<<target<<"' for "<<q->getRemote()<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"failed: not doing AXFR of an NSEC3 narrow zone"<<endl;
       outpacket->setRcode(RCode::Refused);
       sendPacket(outpacket,outsock);
       return 0;
@@ -570,18 +574,18 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
       algorithm = DNSName("hmac-md5");
 
     if(!db.getTSIGKey(tsigkeyname, &algorithm, &tsig64)) {
-      g_log<<Logger::Warning<<"TSIG key '"<<tsigkeyname<<"' for domain '"<<target<<"' not found"<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"TSIG key not found"<<endl;
       return 0;
     }
     if (B64Decode(tsig64, tsigsecret) == -1) {
-      g_log<<Logger::Error<<"Unable to Base-64 decode TSIG key '"<<tsigkeyname<<"' for domain '"<<target<<"'"<<endl;
+      g_log<<Logger::Error<<logPrefix<<"unable to Base-64 decode TSIG key '"<<tsigkeyname<<"'"<<endl;
       return 0;
     }
   }
   
   
   // SOA *must* go out first, our signing pipe might reorder
-  DLOG(g_log<<"Sending out SOA"<<endl);
+  DLOG(g_log<<logPrefix<<"sending out SOA"<<endl);
   DNSZoneRecord soa = makeEditedDNSZRFromSOAData(dk, sd);
   outpacket->addRecord(DNSZoneRecord(soa));
   if(securedZone && !presignedZone) {
@@ -697,7 +701,7 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
   
   // now start list zone
   if(!(sd.db->list(target, sd.domain_id))) {  
-    g_log<<Logger::Error<<"Backend signals error condition"<<endl;
+    g_log<<Logger::Error<<logPrefix<<"backend signals error condition, aborting AXFR"<<endl;
     outpacket->setRcode(RCode::ServFail);
     sendPacket(outpacket,outsock);
     return 0;
@@ -723,7 +727,7 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
         int ret1 = stubDoResolve(getRR<ALIASRecordContent>(zrr.dr)->d_content, QType::A, ips);
         int ret2 = stubDoResolve(getRR<ALIASRecordContent>(zrr.dr)->d_content, QType::AAAA, ips);
         if(ret1 != RCode::NoError || ret2 != RCode::NoError) {
-          g_log<<Logger::Warning<<"Error resolving for ALIAS "<<zrr.dr.d_content->getZoneRepresentation()<<", aborting AXFR"<<endl;
+          g_log<<Logger::Warning<<logPrefix<<"error resolving for ALIAS "<<zrr.dr.d_content->getZoneRepresentation()<<", aborting AXFR"<<endl;
           outpacket->setRcode(RCode::ServFail);
           sendPacket(outpacket,outsock);
           return 0;
@@ -749,7 +753,7 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
       zrrs.push_back(zrr);
     } else {
       if (zrr.dr.d_type)
-        g_log<<Logger::Warning<<"Zone '"<<target<<"' contains out-of-zone data '"<<zrr.dr.d_name<<"|"<<DNSRecordContent::NumberToType(zrr.dr.d_type)<<"', ignoring"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"zone contains out-of-zone data '"<<zrr.dr.d_name<<"|"<<DNSRecordContent::NumberToType(zrr.dr.d_type)<<"', ignoring"<<endl;
     }
   }
 
@@ -807,7 +811,9 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
         while(shorter != target && shorter.chopOff()) {
           if(!qnames.count(shorter) && !nonterm.count(shorter) && nsec3set.count(shorter)) {
             if(!(maxent)) {
-              g_log<<Logger::Warning<<"Zone '"<<target<<"' has too many empty non terminals."<<endl;
+              g_log<<Logger::Warning<<logPrefix<<"zone has too many empty non terminals, aborting AXFR"<<endl;
+              outpacket->setRcode(RCode::ServFail);
+              sendPacket(outpacket,outsock);
               return 0;
             }
             nonterm.insert(shorter);
@@ -990,9 +996,9 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
   
   udiff=dt.udiffNoReset();
   if(securedZone) 
-    g_log<<Logger::Debug<<"Done signing: "<<csp.d_signed/(udiff/1000000.0)<<" sigs/s, "<<endl;
+    g_log<<Logger::Debug<<logPrefix<<"done signing: "<<csp.d_signed/(udiff/1000000.0)<<" sigs/s, "<<endl;
   
-  DLOG(g_log<<"Done writing out records"<<endl);
+  DLOG(g_log<<logPrefix<<"done writing out records"<<endl);
   /* and terminate with yet again the SOA record */
   outpacket=getFreshAXFRPacket(q);
   outpacket->addRecord(std::move(soa));
@@ -1001,14 +1007,16 @@ int TCPNameserver::doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q,
   
   sendPacket(outpacket, outsock);
   
-  DLOG(g_log<<"last packet - close"<<endl);
-  g_log<<Logger::Notice<<"AXFR of domain '"<<target<<"' to "<<q->getRemote()<<" finished"<<endl;
+  DLOG(g_log<<logPrefix<<"last packet - close"<<endl);
+  g_log<<Logger::Notice<<logPrefix<<"AXFR finished"<<endl;
 
   return 1;
 }
 
 int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
 {
+  string logPrefix="IXFR-out zone '"+q->qdomain.toLogString()+"', client '"+q->getRemote().toStringWithPort()+"', ";
+
   std::unique_ptr<DNSPacket> outpacket=getFreshAXFRPacket(q);
   if(q->d_dnssecOk)
     outpacket->d_dnssecOk=true; // RFC 5936, 2.2.5 'SHOULD'
@@ -1025,26 +1033,26 @@ int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
           serial=pdns_stou(parts[2]);
         }
         catch(const std::out_of_range& oor) {
-          g_log<<Logger::Warning<<"Invalid serial in IXFR query"<<endl;
+          g_log<<Logger::Warning<<logPrefix<<"invalid serial in IXFR query"<<endl;
           outpacket->setRcode(RCode::FormErr);
           sendPacket(outpacket,outsock);
           return 0;
         }
       } else {
-        g_log<<Logger::Warning<<"No serial in IXFR query"<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"no serial in IXFR query"<<endl;
         outpacket->setRcode(RCode::FormErr);
         sendPacket(outpacket,outsock);
         return 0;
       }
     } else if (rr->d_type != QType::TSIG && rr->d_type != QType::OPT) {
-      g_log<<Logger::Warning<<"Additional records in IXFR query, type: "<<QType(rr->d_type).getName()<<endl;
+      g_log<<Logger::Warning<<logPrefix<<"additional records in IXFR query, type: "<<QType(rr->d_type).getName()<<endl;
       outpacket->setRcode(RCode::FormErr);
       sendPacket(outpacket,outsock);
       return 0;
     }
   }
 
-  g_log<<Logger::Warning<<"IXFR of domain '"<<q->qdomain<<"' initiated by "<<q->getRemote()<<" with serial "<<serial<<endl;
+  g_log<<Logger::Warning<<logPrefix<<"transfer initiated with serial "<<serial<<endl;
 
   // determine if zone exists, XFR is allowed, and if IXFR can proceed using existing backend before spawning a new backend.
   SOAData sd;
@@ -1052,15 +1060,15 @@ int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
   bool serialPermitsIXFR;
   {
     std::lock_guard<std::mutex> l(s_plock);
-    DLOG(g_log<<"Looking for SOA"<<endl); // find domain_id via SOA and list complete domain. No SOA, no IXFR
+    DLOG(g_log<<logPrefix<<"Looking for SOA"<<endl); // find domain_id via SOA and list complete domain. No SOA, no IXFR
     if(!s_P) {
       g_log<<Logger::Warning<<"TCP server is without backend connections in doIXFR, launching"<<endl;
       s_P=make_unique<PacketHandler>();
     }
 
     // canDoAXFR does all the ACL checks, and has the if(disable-axfr) shortcut, call it first.
-    if(!canDoAXFR(q) || !s_P->getBackend()->getSOAUncached(q->qdomain, sd)) {
-      g_log<<Logger::Warning<<"IXFR of domain '"<<q->qdomain<<"' failed: not authoritative"<<endl;
+    if(!canDoAXFR(q, false) || !s_P->getBackend()->getSOAUncached(q->qdomain, sd)) {
+      g_log<<Logger::Warning<<logPrefix<<"failed: not authoritative"<<endl;
       outpacket->setRcode(RCode::NotAuth);
       sendPacket(outpacket,outsock);
       return 0;
@@ -1072,7 +1080,7 @@ int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
     securedZone = dk.isSecuredZone(q->qdomain);
     if(dk.getNSEC3PARAM(q->qdomain, nullptr, &narrow)) {
       if(narrow) {
-        g_log<<Logger::Warning<<"Not doing IXFR of an NSEC3 narrow zone '"<<q->qdomain<<"' for "<<q->getRemote()<<endl;
+        g_log<<Logger::Warning<<logPrefix<<"not doing IXFR of an NSEC3 narrow zone"<<endl;
         outpacket->setRcode(RCode::Refused);
         sendPacket(outpacket,outsock);
         return 0;
@@ -1099,17 +1107,17 @@ int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
       if (algorithm == DNSName("hmac-md5.sig-alg.reg.int"))
         algorithm = DNSName("hmac-md5");
       if(!db.getTSIGKey(tsigkeyname, &algorithm, &tsig64)) {
-        g_log<<Logger::Error<<"TSIG key '"<<tsigkeyname<<"' for domain '"<<target<<"' not found"<<endl;
+        g_log<<Logger::Error<<logPrefix<<"TSIG key '"<<tsigkeyname<<"' not found"<<endl;
         return 0;
       }
       if (B64Decode(tsig64, tsigsecret) == -1) {
-        g_log<<Logger::Error<<"Unable to Base-64 decode TSIG key '"<<tsigkeyname<<"' for domain '"<<target<<"'"<<endl;
+        g_log<<Logger::Error<<logPrefix<<"unable to Base-64 decode TSIG key '"<<tsigkeyname<<"'"<<endl;
         return 0;
       }
     }
 
     // SOA *must* go out first, our signing pipe might reorder
-    DLOG(g_log<<"Sending out SOA"<<endl);
+    DLOG(g_log<<logPrefix<<"sending out SOA"<<endl);
     DNSZoneRecord soa = makeEditedDNSZRFromSOAData(dk, sd);
     outpacket->addRecord(std::move(soa));
     if(securedZone && outpacket->d_dnssecOk) {
@@ -1123,12 +1131,12 @@ int TCPNameserver::doIXFR(std::unique_ptr<DNSPacket>& q, int outsock)
 
     sendPacket(outpacket, outsock);
 
-    g_log<<Logger::Error<<"IXFR of domain '"<<target<<"' to "<<q->getRemote()<<" finished"<<endl;
+    g_log<<Logger::Notice<<logPrefix<<"IXFR finished"<<endl;
 
     return 1;
   }
 
-  g_log<<Logger::Error<<"IXFR fallback to AXFR for domain '"<<q->qdomain<<"' our serial "<<sd.serial<<endl;
+  g_log<<Logger::Notice<<logPrefix<<"IXFR fallback to AXFR"<<endl;
   return doAXFR(q->qdomain, q, outsock);
 }
 
diff --git a/pdns/tcpreceiver.hh b/pdns/tcpreceiver.hh
index 5220d5b5f2..8d538a7237 100644
--- a/pdns/tcpreceiver.hh
+++ b/pdns/tcpreceiver.hh
@@ -53,7 +53,7 @@ private:
   static void getQuestion(int fd, char *mesg, int pktlen, const ComboAddress& remote, unsigned int totalTime);
   static int doAXFR(const DNSName &target, std::unique_ptr<DNSPacket>& q, int outsock);
   static int doIXFR(std::unique_ptr<DNSPacket>& q, int outsock);
-  static bool canDoAXFR(std::unique_ptr<DNSPacket>& q);
+  static bool canDoAXFR(std::unique_ptr<DNSPacket>& q, bool isAXFR);
   static void doConnection(int fd);
   static void decrementClientCount(const ComboAddress& remote);
   void thread(void);