add a lot of dnssec trace logging

diff --git a/pdns/validate-recursor.cc b/pdns/validate-recursor.cc
index 227f9ddf8163629858bf0ff874d303bfefff0236..eae00a61d4e064cf787a77bffac2340a2cc6922f 100644 (file)
--- 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 8e322fbd64f1443f1006b7d4905a68ccc58e6627..25b6e9b4d6d82b4d7a24af35c9343e0a16b48094 100644 (file)
--- 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,