[v9_11] enhanced rfc 5011 logging

4642.	[cleanup]	Add more logging of RFC 5011 events affecting the
			status of managed keys: newly observed keys,
			deletion of revoked keys, etc. [RT #45354]

(cherry picked from commit 0d90835d2a5df335f398f131589c5c8e266dcd5f)

diff --git a/CHANGES b/CHANGES
index f45e313d8a79fd54a2e6b2f19adeff58da639b7b..02605a632bcc490c4b942db5b95fa5342bd49c9f 100644 (file)
--- a/CHANGES
+++ b/CHANGES
@@ -1,5 +1,9 @@
        --- 9.11.2b1 released ---
 
+4642.  [cleanup]       Add more logging of RFC 5011 events affecting the
+                       status of managed keys: newly observed keys,
+                       deletion of revoked keys, etc. [RT #45354]
+
 4641.  [cleanup]       Parallel builds (make -j) could fail with --with-atf /
                        --enable-developer. [RT #45373]
 

diff --git a/bin/tests/system/mkeys/tests.sh b/bin/tests/system/mkeys/tests.sh
index 199ada144f4e3b5d71f3a2a6f38bac9693a4b3e0..797821445d4cf3b7fd0f8b4ce8aa27fcee8860ec 100644 (file)
--- a/bin/tests/system/mkeys/tests.sh
+++ b/bin/tests/system/mkeys/tests.sh
@@ -379,7 +379,7 @@ $SETTIME -D now -K ns1 $standby1 > /dev/null
 $SETTIME -D now -K ns1 $standby2 > /dev/null
 $SIGNER -Sg -K ns1 -N unixtime -r $RANDFILE -o . ns1/root.db > /dev/null 2>&-
 cp ns1/named2.conf ns1/named.conf
-rm ns1/root.db.signed.jnl
+rm -f ns1/root.db.signed.jnl
 $RNDC -c ../common/rndc.conf -s 10.53.0.1 -p 9953 reconfig
 
 echo "I: reinitialize trust anchors"
@@ -521,7 +521,7 @@ status=`expr $status + $ret`
 
 n=`expr $n + 1`
 echo "I: restore root server, check validation succeeds again ($n)"
-rm ns1/root.db.signed.jnl
+rm -f ns1/root.db.signed.jnl
 $SIGNER -Sg -K ns1 -N unixtime -r $RANDFILE -o . ns1/root.db > /dev/null 2>&-
 $RNDC -c ../common/rndc.conf -s 10.53.0.1 -p 9953 reload . | sed 's/^/I: ns1 /'
 sleep 3

diff --git a/lib/dns/zone.c b/lib/dns/zone.c
index 07d423bc591b63c1691cfce3bc4cfb02f346b508..f5150acd602c72583b1b4d0808e15873627f56e3 100644 (file)
--- a/lib/dns/zone.c
+++ b/lib/dns/zone.c
@@ -8829,7 +8829,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
        dst_key_t *dstkey;
        isc_stdtime_t now;
        int pending = 0;
-       isc_boolean_t secure;
+       isc_boolean_t secure = ISC_FALSE;
        isc_boolean_t free_needed;
 
        UNUSED(task);
@@ -8872,6 +8872,10 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
        if (alldone)
                DNS_ZONE_CLRFLAG(zone, DNS_ZONEFLG_REFRESHING);
 
+       dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                    "Returned from key fetch in keyfetch_done() for "
+                    "'%s': %s", namebuf, dns_result_totext(eresult));
+
        /* Fetch failed */
        if (eresult != ISC_R_SUCCESS ||
            !dns_rdataset_isassociated(&kfetch->dnskeyset)) {
@@ -8952,15 +8956,22 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                if (keynode != NULL)
                        dns_keytable_detachkeynode(secroots, &keynode);
 
-               if (kfetch->dnskeyset.trust == dns_trust_secure)
+               if (kfetch->dnskeyset.trust == dns_trust_secure) {
+                       secure = ISC_TRUE;
                        break;
+               }
        }
 
        /*
         * If we were not able to verify the answer using the current
         * trusted keys then all we can do is look at any revoked keys.
         */
-       secure = ISC_TF(kfetch->dnskeyset.trust == dns_trust_secure);
+
+       if (!secure) {
+               dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                            "DNSKEY set for zone '%s' could not be verified "
+                            "with current keys", namebuf);
+       }
 
        /*
         * First scan keydataset to find keys that are not in dnskeyset
@@ -8978,12 +8989,19 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
        initializing = ISC_TRUE;
        for (result = dns_rdataset_first(&kfetch->keydataset);
             result == ISC_R_SUCCESS;
-            result = dns_rdataset_next(&kfetch->keydataset)) {
+            result = dns_rdataset_next(&kfetch->keydataset))
+       {
+               dns_keytag_t keytag;
+
                dns_rdata_reset(&keydatarr);
                dns_rdataset_current(&kfetch->keydataset, &keydatarr);
                result = dns_rdata_tostruct(&keydatarr, &keydata, NULL);
                RUNTIME_CHECK(result == ISC_R_SUCCESS);
 
+               dns_keydata_todnskey(&keydata, &dnskey, NULL);
+               result = compute_tag(keyname, &dnskey, mctx, &keytag);
+               RUNTIME_CHECK(result == ISC_R_SUCCESS);
+
                /*
                 * If any keydata record has a nonzero add holddown, then
                 * there was a pre-existing trust anchor for this domain;
@@ -8997,27 +9015,35 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
 
                        if (!secure) {
                                if (keydata.removehd != 0 &&
-                                   keydata.removehd <= now)
+                                   keydata.removehd <= now) {
                                        deletekey = ISC_TRUE;
+                               }
                        } else if (keydata.addhd == 0) {
                                deletekey = ISC_TRUE;
                        } else if (keydata.addhd > now) {
-                               dns_zone_log(zone, ISC_LOG_WARNING,
-                                            "Pending key unexpectedly missing "
-                                            "from %s; restarting acceptance "
-                                            "timer", namebuf);
+                               dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                            "Pending key %d for zone %s "
+                                            "unexpectedly missing "
+                                            "restarting 30-day acceptance "
+                                            "timer", keytag, namebuf);
                                if (keydata.addhd < now + dns_zone_mkey_month)
                                        keydata.addhd =
                                                now + dns_zone_mkey_month;
                                keydata.refresh = refresh_time(kfetch,
                                                               ISC_FALSE);
                        } else if (keydata.removehd == 0) {
-                               dns_zone_log(zone, ISC_LOG_WARNING,
-                                            "Active key unexpectedly missing "
-                                            "from %s", namebuf);
+                               dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                            "Active key %d for zone %s "
+                                            "unexpectedly missing",
+                                            keytag, namebuf);
                                keydata.refresh = now + dns_zone_mkey_hour;
                        } else if (keydata.removehd <= now) {
                                deletekey = ISC_TRUE;
+                               dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                            "Revoked key %d for zone %s "
+                                            "missing: deleting from "
+                                            "managed keys database",
+                                            keytag, namebuf);
                        } else {
                                keydata.refresh = refresh_time(kfetch,
                                                               ISC_FALSE);
@@ -9073,6 +9099,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                isc_boolean_t updatekey = ISC_FALSE;
                isc_boolean_t deletekey = ISC_FALSE;
                isc_boolean_t trustkey = ISC_FALSE;
+               dns_keytag_t keytag;
 
                dns_rdata_reset(&dnskeyrr);
                dns_rdataset_current(&kfetch->dnskeyset, &dnskeyrr);
@@ -9083,6 +9110,9 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                if (!ISC_TF(dnskey.flags & DNS_KEYFLAG_KSK))
                        continue;
 
+               result = compute_tag(keyname, &dnskey, mctx, &keytag);
+               RUNTIME_CHECK(result == ISC_R_SUCCESS);
+
                revoked = ISC_TF(dnskey.flags & DNS_KEYFLAG_REVOKE);
 
                if (matchkey(&kfetch->keydataset, &dnskeyrr)) {
@@ -9098,6 +9128,13 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                                         * it's been revoked?  Just remove it
                                         */
                                        deletekey = ISC_TRUE;
+                                       dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                                    "Pending key %d "
+                                                    "for zone %s is now "
+                                                    "revoked: "
+                                                    "deleting from the "
+                                                    "managed keys database",
+                                                    keytag, namebuf);
                                } else if (keydata.removehd == 0) {
                                        /*
                                         * Remove key from secroots.
@@ -9114,16 +9151,30 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                                                keydata.flags |=
                                                        DNS_KEYFLAG_REVOKE;
                                        }
+
+                                       dns_zone_log(zone, ISC_LOG_INFO,
+                                                    "Trusted key %d "
+                                                    "for zone %s is now "
+                                                    "revoked",
+                                                    keytag, namebuf);
                                } else if (keydata.removehd < now) {
                                        /* Scheduled for removal */
                                        deletekey = ISC_TRUE;
+
+                                       dns_zone_log(zone, ISC_LOG_INFO,
+                                                    "Revoked key %d "
+                                                    "for zone %s removal "
+                                                    "timer complete: "
+                                                    "deleting from the "
+                                                    "managed keys database",
+                                                    keytag, namebuf);
                                }
                        } else if (revoked && keydata.removehd == 0) {
                                dns_zone_log(zone, ISC_LOG_WARNING,
-                                            "Active key for zone "
-                                            "'%s' is revoked but "
+                                            "Active key %d for zone "
+                                            "%s is revoked but "
                                             "did not self-sign; "
-                                            "ignoring.", namebuf);
+                                            "ignoring", keytag, namebuf);
                                        continue;
                        } else if (secure) {
                                if (keydata.removehd != 0) {
@@ -9132,20 +9183,34 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                                         * seems it used to be.
                                         * Remove it now and add it
                                         * back as if it were a fresh key,
-                                        * with a 30 day acceptance timer.
+                                        * with a 30-day acceptance timer.
                                         */
                                        deletekey = ISC_TRUE;
                                        newkey = ISC_TRUE;
                                        keydata.removehd = 0;
                                        keydata.addhd =
                                                now + dns_zone_mkey_month;
+
+                                       dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                                    "Revoked key %d "
+                                                    "for zone %s "
+                                                    "has returned: starting "
+                                                    "30-day acceptance timer",
+                                                    keytag, namebuf);
                                } else if (keydata.addhd > now)
                                        pending++;
                                else if (keydata.addhd == 0)
                                        keydata.addhd = now;
 
-                               if (keydata.addhd <= now)
+                               if (keydata.addhd <= now) {
                                        trustkey = ISC_TRUE;
+                                       dns_zone_log(zone, ISC_LOG_INFO,
+                                                    "Key %d for zone %s "
+                                                    "acceptance timer "
+                                                    "complete: "
+                                                    "key now trusted",
+                                                    keytag, namebuf);
+                               }
                        } else if (keydata.addhd > now) {
                                /*
                                 * Not secure, and key is pending:
@@ -9153,6 +9218,12 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                                 */
                                pending++;
                                keydata.addhd = now + dns_zone_mkey_month;
+                               dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                            "Pending key %d "
+                                            "for zone %s was "
+                                            "not validated: restarting "
+                                            "30-day acceptance timer",
+                                            keytag, namebuf);
                        }
 
                        if (!deletekey && !newkey)
@@ -9169,17 +9240,21 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
                        newkey = ISC_TRUE;
 
                        if (initializing) {
-                               dns_keytag_t tag = 0;
-                               CHECK(compute_tag(keyname, &dnskey,
-                                                 mctx, &tag));
                                dns_zone_log(zone, ISC_LOG_WARNING,
                                             "Initializing automatic trust "
                                             "anchor management for zone '%s'; "
                                             "DNSKEY ID %d is now trusted, "
                                             "waiving the normal 30-day "
                                             "waiting period.",
-                                            namebuf, tag);
+                                            namebuf, keytag);
                                trustkey = ISC_TRUE;
+                       } else {
+                               dns_zone_log(zone, ISC_LOG_INFO,
+                                            "New key %d observed "
+                                            "for zone '%s': "
+                                            "starting 30-day "
+                                            "acceptance timer",
+                                            keytag, namebuf);
                        }
                } else {
                        /*
@@ -9410,6 +9485,16 @@ zone_refreshkeys(dns_zone_t *zone) {
                dns_db_attach(db, &kfetch->db);
                kfetch->fetch = NULL;
 
+               if (isc_log_wouldlog(dns_lctx, ISC_LOG_DEBUG(3))) {
+                       char namebuf[DNS_NAME_FORMATSIZE];
+                       dns_name_format(kname, namebuf,
+                                       sizeof(namebuf));
+                       dns_zone_log(zone, ISC_LOG_DEBUG(3),
+                                    "Creating key fetch in "
+                                    "zone_refreshkeys() for '%s'",
+                                    namebuf);
+               }
+
                result = dns_resolver_createfetch(zone->view->resolver,
                                                  kname, dns_rdatatype_dnskey,
                                                  NULL, NULL, NULL,