From: bert hubert <bert.hubert@netherlabs.nl>
Date: Wed, 22 Jun 2016 14:42:11 +0000 (+0200)
Subject: add a lot of dnssec trace logging
X-Git-Tag: auth-4.0.0-rc1~20^2
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=a95d1b582d54b1ef217c852e038950e1a4ccfaa4;p=pdns

add a lot of dnssec trace logging
---

diff --git a/pdns/validate-recursor.cc b/pdns/validate-recursor.cc
index 227f9ddf8..eae00a61d 100644
--- a/pdns/validate-recursor.cc
+++ b/pdns/validate-recursor.cc
@@ -52,6 +52,9 @@ vState validateRecords(const vector<DNSRecord>& recs)
         if(state == NTA)
           return Insecure;
         LOG("! state = "<<vStates[state]<<", now have "<<keys.size()<<" keys"<<endl);
+        for(const auto& k : keys) {
+          LOG("Key: "<<k.getZoneRepresentation()<< " {tag="<<k.getTag()<<"}"<<endl);
+        }
         // this sort of charges on and 'state' ends up as the last thing to have been checked
         // maybe not the right idea
       }
@@ -90,9 +93,9 @@ vState validateRecords(const vector<DNSRecord>& recs)
 #endif
   //  cerr<<"Input to validate: "<<endl;
   for(const auto& csp : cspmap) {
-    LOG(csp.first.first<<"|"<<csp.first.second<<" with "<<csp.second.signatures.size()<<" signatures"<<endl);
+    LOG(csp.first.first<<"|"<<DNSRecordContent::NumberToType(csp.first.second)<<" with "<<csp.second.signatures.size()<<" signatures"<<endl);
     if(!csp.second.signatures.empty() && !validrrsets.count(csp.first)) {
-      LOG("Lacks signature, must have one"<<endl);
+      LOG("Lacks signature, must have one, signatures: "<<csp.second.signatures.size()<<", valid rrsets: "<<validrrsets.count(csp.first)<<endl);
       return Bogus;
     }
   }
diff --git a/pdns/validate.cc b/pdns/validate.cc
index 8e322fbd6..25b6e9b4d 100644
--- a/pdns/validate.cc
+++ b/pdns/validate.cc
@@ -88,12 +88,12 @@ void validateWithKeySet(const cspmap_t& rrsets, cspmap_t& validated, const keyse
   }
   */
   for(auto i=rrsets.begin(); i!=rrsets.end(); i++) {
-    //    cerr<<"validating "<<(i->first.first)<<"/"<<DNSRecordContent::NumberToType(i->first.second)<<" with "<<i->second.signatures.size()<<" sigs: ";
+    LOG("validating "<<(i->first.first)<<"/"<<DNSRecordContent::NumberToType(i->first.second)<<" with "<<i->second.signatures.size()<<" sigs"<<endl);
     for(const auto& signature : i->second.signatures) {
       vector<shared_ptr<DNSRecordContent> > toSign = i->second.records;
       
       if(getByTag(keys,signature->d_tag).empty()) {
-	//	cerr<<"No key provided for "<<signature->d_tag<<endl;
+	LOG("No key provided for "<<signature->d_tag<<endl;);
 	continue;
       }
       
@@ -106,6 +106,7 @@ void validateWithKeySet(const cspmap_t& rrsets, cspmap_t& validated, const keyse
 	  if(signature->d_siginception < now && signature->d_sigexpire > now) {
 	    std::shared_ptr<DNSCryptoKeyEngine> dke = shared_ptr<DNSCryptoKeyEngine>(DNSCryptoKeyEngine::makeFromPublicKeyString(l.d_algorithm, l.d_key));
 	    isValid = dke->verify(msg, signature->d_signature);
+            LOG("signature by key with tag "<<signature->d_tag<<" was " << (isValid ? "" : "NOT ")<<"valid"<<endl);
 	  }
 	  else {
 	    LOG("signature is expired/not yet valid"<<endl);
@@ -116,8 +117,9 @@ void validateWithKeySet(const cspmap_t& rrsets, cspmap_t& validated, const keyse
 	}
 	if(isValid) {
 	  validated[i->first] = i->second;
+          LOG("Validated "<<i->first.first<<"/"<<DNSRecordContent::NumberToType(signature->d_type)<<endl);
 	  //	  cerr<<"valid"<<endl;
-	  //	  cerr<<"! validated "<<i->first.first<<"/"<<DNSRecordContent::NumberToType(signature->d_type)<<endl;
+	  //	  cerr<<"! validated "<<i->first.first<<"/"<<)<<endl;
 	}
 	else {
           LOG("signature invalid"<<endl);
@@ -239,6 +241,7 @@ vState getKeysFor(DNSRecordOracle& dro, const DNSName& zone, keyset_t &keyset)
       if(rec.d_type == QType::RRSIG)
       {
         auto rrc=getRR<RRSIGRecordContent> (rec);
+        LOG("Got signature: "<<rrc->getZoneRepresentation()<<" with tag "<<rrc->d_tag<<", for type "<<DNSRecordContent::NumberToType(rrc->d_type)<<endl);
         if(rrc && rrc->d_type != QType::DNSKEY)
           continue;
         sigs.push_back(*rrc);
@@ -248,15 +251,15 @@ vState getKeysFor(DNSRecordOracle& dro, const DNSName& zone, keyset_t &keyset)
         auto drc=getRR<DNSKEYRecordContent> (rec);
         if(drc) {
           tkeys.insert(*drc);
-          //	cerr<<"Inserting key with tag "<<drc->getTag()<<": "<<drc->getZoneRepresentation()<<endl;
-          dotNode("DNSKEY", qname, std::to_string(drc->getTag()), (boost::format("tag=%d, algo=%d") % drc->getTag() % static_cast<int>(drc->d_algorithm)).str());
+          LOG("Inserting key with tag "<<drc->getTag()<<": "<<drc->getZoneRepresentation()<<endl);
+          //          dotNode("DNSKEY", qname, std::to_string(drc->getTag()), (boost::format("tag=%d, algo=%d") % drc->getTag() % static_cast<int>(drc->d_algorithm)).str());
 
           toSign.push_back(rec.d_content);
           toSignTags.push_back(drc->getTag());
         }
       }
     }
-    //    cerr<<"got "<<tkeys.size()<<" keys and "<<sigs.size()<<" sigs from server"<<endl;
+    LOG("got "<<tkeys.size()<<" keys and "<<sigs.size()<<" sigs from server"<<endl);
 
     for(dsmap_t::const_iterator i=dsmap.begin(); i!=dsmap.end(); i++)
     {
@@ -273,11 +276,11 @@ vState getKeysFor(DNSRecordOracle& dro, const DNSName& zone, keyset_t &keyset)
 	  isValid = dsrc == dsrc2;
 	} 
 	catch(std::exception &e) {
-	  //	  cerr<<"Unable to make DS from DNSKey: "<<e.what()<<endl;
+	  LOG("Unable to make DS from DNSKey: "<<e.what()<<endl);
 	}
 
         if(isValid) {
-	  LOG("got valid DNSKEY (it matches the DS) for "<<qname<<endl);
+	  LOG("got valid DNSKEY (it matches the DS) with tag "<<dsrc.d_tag<<"/"<<i->first<<" for "<<qname<<endl);
 	  
           validkeys.insert(drc);
 	  dotNode("DS", qname, "" /*std::to_string(dsrc.d_tag)*/, (boost::format("tag=%d, digest algo=%d, algo=%d") % dsrc.d_tag % static_cast<int>(dsrc.d_digesttype) % static_cast<int>(dsrc.d_algorithm)).str());
@@ -316,7 +319,7 @@ vState getKeysFor(DNSRecordOracle& dro, const DNSName& zone, keyset_t &keyset)
 	    }
 	  }
 	  catch(std::exception& e) {
-	    //	    cerr<<"Could not make a validator for signature: "<<e.what()<<endl;
+	    LOG("Could not make a validator for signature: "<<e.what()<<endl);
 	  }
 	  for(uint16_t tag : toSignTags) {
 	    dotEdge(qname,