From: Evan Hunt Date: Tue, 27 Jun 2017 17:50:29 +0000 (-0700) Subject: [v9_11] enhanced rfc 5011 logging X-Git-Tag: v9.11.2b1~7 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d315545e6db6792692fe2dcb788ac6717a33b75f;p=thirdparty%2Fbind9.git [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 f45e313d8a7..02605a632bc 100644 --- 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 199ada144f4..797821445d4 100644 --- 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 07d423bc591..f5150acd602 100644 --- 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,