Cleanup log statements

dnsjava · ibauersachs · Jan 23, 2022 · Aug 15, 2021 · Aug 15, 2021 · Aug 21, 2021
commit b37ba4521c6c300740417b9c8e646fbfbaab97fa
diff --git a/src/main/java/org/xbill/DNS/dnssec/DnsSecVerifier.java b/src/main/java/org/xbill/DNS/dnssec/DnsSecVerifier.java
@@ -41,7 +41,7 @@ final class DnsSecVerifier {
   private List<DNSKEYRecord> findKey(RRset dnskeyRrset, RRSIGRecord signature) {
     if (!signature.getSigner().equals(dnskeyRrset.getName())) {
       log.trace(
-          "could not find appropriate key because incorrect keyset was supplied. Wanted: {}, got: {}",
+          "Could not find appropriate key because incorrect keyset was supplied. Wanted: {}, got: {}",
           signature.getSigner(),
           dnskeyRrset.getName());
       return Collections.emptyList();
@@ -74,7 +74,7 @@ private List<DNSKEYRecord> findKey(RRset dnskeyRrset, RRSIGRecord signature) {
   private JustifiedSecStatus verifySignature(
       SRRset rrset, RRSIGRecord sigrec, RRset keyRrset, Instant date) {
     if (!rrset.getName().subdomain(keyRrset.getName())) {
-      log.debug("signer name is off-tree");
+      log.debug("Signer name is off-tree");
       return new JustifiedSecStatus(
           SecurityStatus.BOGUS,
           ExtendedErrorCodeOption.DNSSEC_BOGUS,
@@ -83,7 +83,7 @@ private JustifiedSecStatus verifySignature(
 
     List<DNSKEYRecord> keys = this.findKey(keyRrset, sigrec);
     if (keys.isEmpty()) {
-      log.trace("could not find appropriate key");
+      log.trace("Could not find appropriate key");
       return new JustifiedSecStatus(
           SecurityStatus.BOGUS,
           ExtendedErrorCodeOption.DNSKEY_MISSING,

diff --git a/src/main/java/org/xbill/DNS/dnssec/KeyEntry.java b/src/main/java/org/xbill/DNS/dnssec/KeyEntry.java
@@ -125,7 +125,7 @@ JustifiedSecStatus validateKeyFor(Name signerName) {
     // signerName being null is the indicator that this response was
     // unsigned
     if (signerName == null) {
-      log.debug("no signerName");
+      log.debug("No signerName");
       // Unsigned responses must be underneath a "null" key entry.
       if (this.isNull()) {
         String reason = this.badReason;

diff --git a/src/main/java/org/xbill/DNS/dnssec/NSEC3ValUtils.java b/src/main/java/org/xbill/DNS/dnssec/NSEC3ValUtils.java
@@ -171,7 +171,7 @@ private NSEC3Record findMatchingNSEC3(Name name, Name zonename, List<SRRset> nse
           return nsec3;
         }
       } catch (NoSuchAlgorithmException | TextParseException e) {
-        log.debug("Unrecognized NSEC3 in set:" + set, e);
+        log.debug("Unrecognized NSEC3 in set: {}", set, e);
       }
     }
 
@@ -228,7 +228,7 @@ private NSEC3Record findCoveringNSEC3(Name name, Name zonename, List<SRRset> nse
           return nsec3;
         }
       } catch (NoSuchAlgorithmException e) {
-        log.debug("Unrecognized NSEC3 in set:" + set, e);
+        log.debug("Unrecognized NSEC3 in set: {}", set, e);
       }
     }
 
@@ -273,14 +273,14 @@ private CEResponse findClosestEncloser(Name name, Name zonename, List<SRRset> ns
   private CEResponse proveClosestEncloser(Name qname, Name zonename, List<SRRset> nsec3s) {
     CEResponse candidate = this.findClosestEncloser(qname, zonename, nsec3s);
     if (candidate == null) {
-      log.debug("proveClosestEncloser: could not find a candidate for the closest encloser.");
+      log.debug("Could not find a candidate for the closest encloser");
       candidate = new CEResponse(Name.empty, null);
       candidate.status = SecurityStatus.BOGUS;
       return candidate;
     }
 
     if (candidate.closestEncloser.equals(qname)) {
-      log.debug("proveClosestEncloser: proved that qname existed!");
+      log.debug("Proved that qname existed!");
       candidate.status = SecurityStatus.BOGUS;
       return candidate;
     }
@@ -294,13 +294,13 @@ private CEResponse proveClosestEncloser(Name qname, Name zonename, List<SRRset>
         return candidate;
       }
 
-      log.debug("proveClosestEncloser: closest encloser was a delegation!");
+      log.debug("Closest encloser was a delegation!");
       candidate.status = SecurityStatus.BOGUS;
       return candidate;
     }
 
     if (candidate.ceNsec3.hasType(Type.DNAME)) {
-      log.debug("proveClosestEncloser: closest encloser was a DNAME!");
+      log.debug("Closest encloser was a DNAME!");
       candidate.status = SecurityStatus.BOGUS;
       return candidate;
     }
@@ -450,7 +450,7 @@ public SecurityStatus proveNameError(List<SRRset> nsec3s, Name qname, Name zonen
     CEResponse ce = this.proveClosestEncloser(qname, zonename, nsec3s);
 
     if (ce.status != SecurityStatus.SECURE) {
-      log.debug("proveNameError: failed to prove a closest encloser.");
+      log.debug("Failed to prove a closest encloser");
       return ce.status;
     }
 
@@ -460,12 +460,12 @@ public SecurityStatus proveNameError(List<SRRset> nsec3s, Name qname, Name zonen
     Name wc = this.ceWildcard(ce.closestEncloser);
     NSEC3Record nsec3 = this.findCoveringNSEC3(wc, zonename, nsec3s);
     if (nsec3 == null) {
-      log.debug("proveNameError: could not prove that the applicable wildcard did not exist.");
+      log.debug("Could not prove that the applicable wildcard did not exist");
       return SecurityStatus.BOGUS;
     }
 
     if ((ce.ncNsec3.getFlags() & Flags.OPT_OUT) == Flags.OPT_OUT) {
-      log.debug("nsec3 nameerror proof: nc has optout");
+      log.debug("NSEC3 nameerror proof: nc has optout");
       return SecurityStatus.INSECURE;
     }
 
@@ -506,28 +506,28 @@ public JustifiedSecStatus proveNodata(List<SRRset> nsec3s, Name qname, int qtype
     // Cases 1 & 2.
     if (nsec3 != null) {
       if (nsec3.hasType(qtype)) {
-        log.debug("proveNodata: Matching NSEC3 proved that type existed!");
+        log.debug("Matching NSEC3 proved that type existed!");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.type_exists"));
       }
 
       if (nsec3.hasType(Type.CNAME)) {
-        log.debug("proveNodata: Matching NSEC3 proved that a CNAME existed!");
+        log.debug("Matching NSEC3 proved that a CNAME existed!");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.cname_exists"));
       }
 
       if (qtype == Type.DS && nsec3.hasType(Type.SOA) && !Name.root.equals(qname)) {
-        log.debug("proveNodata: apex NSEC3 abused for no DS proof, bogus");
+        log.debug("Apex NSEC3 abused for no DS proof, bogus");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.apex_abuse"));
       } else if (qtype != Type.DS && nsec3.hasType(Type.NS) && !nsec3.hasType(Type.SOA)) {
         if (!nsec3.hasType(Type.DS)) {
-          log.debug("proveNodata: matching NSEC3 is insecure delegation");
+          log.debug("Matching NSEC3 is insecure delegation");
           return new JustifiedSecStatus(SecurityStatus.INSECURE, -1, null);
         }
 
-        log.debug("proveNodata: matching NSEC3 is a delegation, bogus");
+        log.debug("Matching NSEC3 is a delegation, bogus");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.delegation"));
       }
@@ -543,11 +543,11 @@ public JustifiedSecStatus proveNodata(List<SRRset> nsec3s, Name qname, int qtype
     // At this point, not finding a match or a proven closest encloser is a
     // problem.
     if (ce.status == SecurityStatus.BOGUS) {
-      log.debug("proveNodata: did not match qname, nor found a proven closest encloser");
+      log.debug("Did not match qname, nor found a proven closest encloser");
       return new JustifiedSecStatus(
           SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.qname_ce"));
     } else if (ce.status == SecurityStatus.INSECURE && qtype != Type.DS) {
-      log.debug("proveNodata: closest nsec3 is insecure delegation");
+      log.debug("Closest NSEC3 is insecure delegation");
       return new JustifiedSecStatus(SecurityStatus.INSECURE, -1, null);
     }
 
@@ -558,27 +558,27 @@ public JustifiedSecStatus proveNodata(List<SRRset> nsec3s, Name qname, int qtype
     nsec3 = this.findMatchingNSEC3(wc, zonename, nsec3s);
     if (nsec3 != null) {
       if (nsec3.hasType(qtype)) {
-        log.debug("proveNodata: matching wildcard had qtype!");
+        log.debug("Matching wildcard has qtype {}", Type.string(qtype));
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.type_exists_wc"));
       } else if (nsec3.hasType(Type.CNAME)) {
-        log.debug("nsec3 nodata proof: matching wildcard had a CNAME, bogus");
+        log.debug("Matching wildcard has a CNAME, bogus");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.cname_exists_wc"));
       }
 
       if (qtype == Type.DS && qname.labels() != 1 && nsec3.hasType(Type.SOA)) {
-        log.debug("nsec3 nodata proof: matching wildcard for no DS proof has a SOA, bogus");
+        log.debug("Matching wildcard for no DS proof has a SOA, bogus");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.wc_soa"));
       } else if (qtype != Type.DS && nsec3.hasType(Type.NS) && !nsec3.hasType(Type.SOA)) {
-        log.debug("nsec3 nodata proof: matching wilcard is a delegation, bogus");
+        log.debug("Matching wildcard is a delegation, bogus");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.delegation_wc"));
       }
 
       if (ce.ncNsec3 != null && (ce.ncNsec3.getFlags() & Flags.OPT_OUT) == Flags.OPT_OUT) {
-        log.debug("nsec3 nodata proof: matching wildcard is in optout range, insecure");
+        log.debug("Matching wildcard is in opt-out range, insecure");
         return new JustifiedSecStatus(SecurityStatus.INSECURE, -1, null);
       }
 
@@ -590,21 +590,20 @@ public JustifiedSecStatus proveNodata(List<SRRset> nsec3s, Name qname, int qtype
     // can see the ordinary unsigned data from a zone beneath an
     // insecure delegation under an optout here */
     if (ce.ncNsec3 == null) {
-      log.debug("nsec3 nodata proof: no next closer nsec3");
+      log.debug("No next closer NSEC3");
       return new JustifiedSecStatus(
           SecurityStatus.BOGUS, NSEC_MISSING, R.get("failed.nsec3.no_next"));
     }
 
     // We need to make sure that the covering NSEC3 is opt-out.
     if ((ce.ncNsec3.getFlags() & Flags.OPT_OUT) == 0) {
       if (qtype != Type.DS) {
-        log.debug(
-            "proveNodata: covering NSEC3 was not opt-out in an opt-out DS NOERROR/NODATA case");
+        log.debug("Covering NSEC3 was not opt-out in an opt-out DS NOERROR/NODATA case");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, DNSSEC_BOGUS, R.get("failed.nsec3.not_optout"));
       } else {
         log.debug(
-            "proveNodata: could not find matching NSEC3, nor matching wildcard, and qtype is not DS -- no more options");
+            "Could not find matching NSEC3, nor matching wildcard, and qtype is not DS -- no more options");
         return new JustifiedSecStatus(
             SecurityStatus.BOGUS, NSEC_MISSING, R.get("failed.nsec3.not_found"));
       }
@@ -640,13 +639,10 @@ public SecurityStatus proveWildcard(
 
     if (candidate.ncNsec3 == null) {
       log.debug(
-          "proveWildcard: did not find a covering NSEC3 that covered the next closer name to "
-              + qname
-              + " from "
-              + candidate.closestEncloser
-              + " (derived from wildcard "
-              + wildcard
-              + ")");
+          "did not find a covering NSEC3 that covered the next closer name to {} from {} (derived from wildcard {})",
+          qname,
+          candidate.closestEncloser,
+          wildcard);
       return SecurityStatus.BOGUS;
     }
 

diff --git a/src/main/java/org/xbill/DNS/dnssec/SMessage.java b/src/main/java/org/xbill/DNS/dnssec/SMessage.java
@@ -197,7 +197,9 @@ public void setStatus(SecurityStatus status, int edeReason, String reason) {
     this.securityStatus = status;
     this.edeReason = edeReason;
     this.bogusReason = reason;
-    log.debug(this.bogusReason);
+    if (reason != null) {
+      log.debug("Setting bad reason for message to {}", reason);
+    }
   }
 
   /**

diff --git a/src/main/java/org/xbill/DNS/dnssec/ValUtils.java b/src/main/java/org/xbill/DNS/dnssec/ValUtils.java
@@ -373,15 +373,12 @@ && isAlgorithmSupported(ds.getAlgorithm())) {
    * @return The status (BOGUS or SECURE).
    */
   public JustifiedSecStatus verifySRRset(SRRset rrset, SRRset keyRrset, Instant date) {
-    String rrsetName =
-        rrset.getName()
-            + "/"
-            + Type.string(rrset.getType())
-            + "/"
-            + DClass.string(rrset.getDClass());
-
     if (rrset.getSecurityStatus() == SecurityStatus.SECURE) {
-      log.trace("verifySRRset: rrset <{}> previously found to be SECURE", rrsetName);
+      log.trace(
+          "RRset <{}/{}/{}> previously found to be SECURE",
+          rrset.getName(),
+          Type.string(rrset.getType()),
+          DClass.string(rrset.getDClass()));
       return new JustifiedSecStatus(SecurityStatus.SECURE, -1, null);
     }
 

diff --git a/src/main/java/org/xbill/DNS/dnssec/ValidatingResolver.java b/src/main/java/org/xbill/DNS/dnssec/ValidatingResolver.java
@@ -154,7 +154,7 @@ public void init(Properties config) throws IOException {
     // Load trust anchors
     String s = config.getProperty("dnsjava.dnssec.trust_anchor_file");
     if (s != null) {
-      log.debug("reading trust anchor file file: " + s);
+      log.debug("Reading trust anchor file: {}", s);
       this.loadTrustAnchors(new FileInputStream(s));
     }
   }
@@ -611,7 +611,7 @@ private CompletionStage<Void> validateNodataResponse(Message request, SMessage r
 
               this.n3valUtils.stripUnknownAlgNSEC3s(nsec3s);
               if (!hasValidNSEC && !nsec3s.isEmpty()) {
-                log.debug("Validating nodata: using NSEC3 records");
+                log.debug("Using NSEC3 records");
 
                 // try to prove NODATA with our NSEC3 record(s)
                 if (this.n3valUtils.allNSEC3sIgnoreable(nsec3s, this.keyCache)) {
@@ -636,7 +636,7 @@ private CompletionStage<Void> validateNodataResponse(Message request, SMessage r
                 return null;
               }
 
-              log.trace("successfully validated NODATA response");
+              log.trace("Successfully validated NODATA response");
               response.setStatus(SecurityStatus.SECURE, -1);
               return null;
             });
@@ -798,7 +798,7 @@ private CompletionStage<Void> validateNameErrorResponse(Message request, SMessag
               }
 
               // Otherwise, we consider the message secure.
-              log.trace("successfully validated NAME ERROR response.");
+              log.trace("Successfully validated NAME ERROR response");
               response.setStatus(SecurityStatus.SECURE, -1);
               return completedFuture(null);
             })
@@ -834,13 +834,10 @@ private CompletionStage<Void> validateNameErrorResponseRecursive(
   private CompletionStage<SMessage> sendRequest(Message request) {
     Record q = request.getQuestion();
     log.trace(
-        "sending request: <"
-            + q.getName()
-            + "/"
-            + Type.string(q.getType())
-            + "/"
-            + DClass.string(q.getDClass())
-            + ">");
+        "Sending request: <{}/{}/{}>",
+        q.getName(),
+        Type.string(q.getType()),
+        DClass.string(q.getDClass()));
 
     // Send the request along by using a local copy of the request
     Message localRequest = request.clone();
@@ -925,12 +922,10 @@ private CompletionStage<Void> processFindKey(FindKeyState state) {
 
     Name nextKeyName = new Name(targetKeyName, l);
     log.trace(
-        "findKey: targetKeyName = "
-            + targetKeyName
-            + ", currentKeyName = "
-            + currentKeyName
-            + ", nextKeyName = "
-            + nextKeyName);
+        "Key search: targetKeyName = {}, currentKeyName = {}, nextKeyName = {}",
+        targetKeyName,
+        currentKeyName,
+        nextKeyName);
 
     // The next step is either to query for the next DS, or to query for the
     // next DNSKEY.
@@ -987,7 +982,7 @@ private KeyEntry dsResponseToKE(SMessage response, Message request, SRRset keyRr
         }
 
         // Otherwise, we return the positive response.
-        log.trace("DS rrset was good.");
+        log.trace("DS RRset was good");
         return KeyEntry.newKeyEntry(dsRrset);
 
       case CNAME:
@@ -1069,7 +1064,7 @@ private KeyEntry dsReponseToKeForNodata(SMessage response, Message request, SRRs
           // We could just fail here as there is an invalid rrset, but
           // skipping doesn't matter because we might not need it or
           // the proof will fail anyway.
-          log.debug("skipping bad nsec3");
+          log.debug("Skipping bad NSEC3");
           continue;
         }
 
@@ -1090,7 +1085,7 @@ private KeyEntry dsReponseToKeForNodata(SMessage response, Message request, SRRs
           nullKey.setBadReason(-1, R.get("insecure.ds.nsec3"));
           return nullKey;
         case INDETERMINATE:
-          log.debug("nsec3s for the referral proved no delegation.");
+          log.debug("NSEC3s for the referral proved no delegation");
           return null;
         case BOGUS:
           bogusKE.setBadReason(ExtendedErrorCodeOption.DNSSEC_BOGUS, R.get("failed.ds.nsec3"));