Commit 0d90835d authored by Evan Hunt's avatar Evan Hunt
Browse files

[master] 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]
parent 90a6f5a7
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 / 4641. [cleanup] Parallel builds (make -j) could fail with --with-atf /
--enable-developer. [RT #45373] --enable-developer. [RT #45373]
......
...@@ -379,7 +379,7 @@ $SETTIME -D now -K ns1 $standby1 > /dev/null ...@@ -379,7 +379,7 @@ $SETTIME -D now -K ns1 $standby1 > /dev/null
$SETTIME -D now -K ns1 $standby2 > /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>&- $SIGNER -Sg -K ns1 -N unixtime -r $RANDFILE -o . ns1/root.db > /dev/null 2>&-
cp ns1/named2.conf ns1/named.conf 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 $RNDC -c ../common/rndc.conf -s 10.53.0.1 -p 9953 reconfig
echo "I: reinitialize trust anchors" echo "I: reinitialize trust anchors"
...@@ -521,7 +521,7 @@ status=`expr $status + $ret` ...@@ -521,7 +521,7 @@ status=`expr $status + $ret`
n=`expr $n + 1` n=`expr $n + 1`
echo "I: restore root server, check validation succeeds again ($n)" 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>&- $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 /' $RNDC -c ../common/rndc.conf -s 10.53.0.1 -p 9953 reload . | sed 's/^/I: ns1 /'
sleep 3 sleep 3
......
...@@ -8799,7 +8799,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -8799,7 +8799,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
dst_key_t *dstkey; dst_key_t *dstkey;
isc_stdtime_t now; isc_stdtime_t now;
int pending = 0; int pending = 0;
isc_boolean_t secure; isc_boolean_t secure = ISC_FALSE;
isc_boolean_t free_needed; isc_boolean_t free_needed;
UNUSED(task); UNUSED(task);
...@@ -8842,6 +8842,10 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -8842,6 +8842,10 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
if (alldone) if (alldone)
DNS_ZONE_CLRFLAG(zone, DNS_ZONEFLG_REFRESHING); 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 */ /* Fetch failed */
if (eresult != ISC_R_SUCCESS || if (eresult != ISC_R_SUCCESS ||
!dns_rdataset_isassociated(&kfetch->dnskeyset)) { !dns_rdataset_isassociated(&kfetch->dnskeyset)) {
...@@ -8922,15 +8926,22 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -8922,15 +8926,22 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
if (keynode != NULL) if (keynode != NULL)
dns_keytable_detachkeynode(secroots, &keynode); dns_keytable_detachkeynode(secroots, &keynode);
if (kfetch->dnskeyset.trust == dns_trust_secure) if (kfetch->dnskeyset.trust == dns_trust_secure) {
secure = ISC_TRUE;
break; break;
}
} }
/* /*
* If we were not able to verify the answer using the current * 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. * 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 * First scan keydataset to find keys that are not in dnskeyset
...@@ -8948,12 +8959,19 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -8948,12 +8959,19 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
initializing = ISC_TRUE; initializing = ISC_TRUE;
for (result = dns_rdataset_first(&kfetch->keydataset); for (result = dns_rdataset_first(&kfetch->keydataset);
result == ISC_R_SUCCESS; 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_rdata_reset(&keydatarr);
dns_rdataset_current(&kfetch->keydataset, &keydatarr); dns_rdataset_current(&kfetch->keydataset, &keydatarr);
result = dns_rdata_tostruct(&keydatarr, &keydata, NULL); result = dns_rdata_tostruct(&keydatarr, &keydata, NULL);
RUNTIME_CHECK(result == ISC_R_SUCCESS); 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 * If any keydata record has a nonzero add holddown, then
* there was a pre-existing trust anchor for this domain; * there was a pre-existing trust anchor for this domain;
...@@ -8967,27 +8985,35 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -8967,27 +8985,35 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
if (!secure) { if (!secure) {
if (keydata.removehd != 0 && if (keydata.removehd != 0 &&
keydata.removehd <= now) keydata.removehd <= now) {
deletekey = ISC_TRUE; deletekey = ISC_TRUE;
}
} else if (keydata.addhd == 0) { } else if (keydata.addhd == 0) {
deletekey = ISC_TRUE; deletekey = ISC_TRUE;
} else if (keydata.addhd > now) { } else if (keydata.addhd > now) {
dns_zone_log(zone, ISC_LOG_WARNING, dns_zone_log(zone, ISC_LOG_DEBUG(3),
"Pending key unexpectedly missing " "Pending key %d for zone %s "
"from %s; restarting acceptance " "unexpectedly missing "
"timer", namebuf); "restarting 30-day acceptance "
"timer", keytag, namebuf);
if (keydata.addhd < now + dns_zone_mkey_month) if (keydata.addhd < now + dns_zone_mkey_month)
keydata.addhd = keydata.addhd =
now + dns_zone_mkey_month; now + dns_zone_mkey_month;
keydata.refresh = refresh_time(kfetch, keydata.refresh = refresh_time(kfetch,
ISC_FALSE); ISC_FALSE);
} else if (keydata.removehd == 0) { } else if (keydata.removehd == 0) {
dns_zone_log(zone, ISC_LOG_WARNING, dns_zone_log(zone, ISC_LOG_DEBUG(3),
"Active key unexpectedly missing " "Active key %d for zone %s "
"from %s", namebuf); "unexpectedly missing",
keytag, namebuf);
keydata.refresh = now + dns_zone_mkey_hour; keydata.refresh = now + dns_zone_mkey_hour;
} else if (keydata.removehd <= now) { } else if (keydata.removehd <= now) {
deletekey = ISC_TRUE; 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 { } else {
keydata.refresh = refresh_time(kfetch, keydata.refresh = refresh_time(kfetch,
ISC_FALSE); ISC_FALSE);
...@@ -9043,6 +9069,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9043,6 +9069,7 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
isc_boolean_t updatekey = ISC_FALSE; isc_boolean_t updatekey = ISC_FALSE;
isc_boolean_t deletekey = ISC_FALSE; isc_boolean_t deletekey = ISC_FALSE;
isc_boolean_t trustkey = ISC_FALSE; isc_boolean_t trustkey = ISC_FALSE;
dns_keytag_t keytag;
dns_rdata_reset(&dnskeyrr); dns_rdata_reset(&dnskeyrr);
dns_rdataset_current(&kfetch->dnskeyset, &dnskeyrr); dns_rdataset_current(&kfetch->dnskeyset, &dnskeyrr);
...@@ -9053,6 +9080,9 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9053,6 +9080,9 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
if (!ISC_TF(dnskey.flags & DNS_KEYFLAG_KSK)) if (!ISC_TF(dnskey.flags & DNS_KEYFLAG_KSK))
continue; continue;
result = compute_tag(keyname, &dnskey, mctx, &keytag);
RUNTIME_CHECK(result == ISC_R_SUCCESS);
revoked = ISC_TF(dnskey.flags & DNS_KEYFLAG_REVOKE); revoked = ISC_TF(dnskey.flags & DNS_KEYFLAG_REVOKE);
if (matchkey(&kfetch->keydataset, &dnskeyrr)) { if (matchkey(&kfetch->keydataset, &dnskeyrr)) {
...@@ -9068,6 +9098,13 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9068,6 +9098,13 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
* it's been revoked? Just remove it * it's been revoked? Just remove it
*/ */
deletekey = ISC_TRUE; 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) { } else if (keydata.removehd == 0) {
/* /*
* Remove key from secroots. * Remove key from secroots.
...@@ -9084,16 +9121,30 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9084,16 +9121,30 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
keydata.flags |= keydata.flags |=
DNS_KEYFLAG_REVOKE; 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) { } else if (keydata.removehd < now) {
/* Scheduled for removal */ /* Scheduled for removal */
deletekey = ISC_TRUE; 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) { } else if (revoked && keydata.removehd == 0) {
dns_zone_log(zone, ISC_LOG_WARNING, dns_zone_log(zone, ISC_LOG_WARNING,
"Active key for zone " "Active key %d for zone "
"'%s' is revoked but " "%s is revoked but "
"did not self-sign; " "did not self-sign; "
"ignoring.", namebuf); "ignoring", keytag, namebuf);
continue; continue;
} else if (secure) { } else if (secure) {
if (keydata.removehd != 0) { if (keydata.removehd != 0) {
...@@ -9102,20 +9153,34 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9102,20 +9153,34 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
* seems it used to be. * seems it used to be.
* Remove it now and add it * Remove it now and add it
* back as if it were a fresh key, * back as if it were a fresh key,
* with a 30 day acceptance timer. * with a 30-day acceptance timer.
*/ */
deletekey = ISC_TRUE; deletekey = ISC_TRUE;
newkey = ISC_TRUE; newkey = ISC_TRUE;
keydata.removehd = 0; keydata.removehd = 0;
keydata.addhd = keydata.addhd =
now + dns_zone_mkey_month; 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) } else if (keydata.addhd > now)
pending++; pending++;
else if (keydata.addhd == 0) else if (keydata.addhd == 0)
keydata.addhd = now; keydata.addhd = now;
if (keydata.addhd <= now) if (keydata.addhd <= now) {
trustkey = ISC_TRUE; 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) { } else if (keydata.addhd > now) {
/* /*
* Not secure, and key is pending: * Not secure, and key is pending:
...@@ -9123,6 +9188,12 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9123,6 +9188,12 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
*/ */
pending++; pending++;
keydata.addhd = now + dns_zone_mkey_month; 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) if (!deletekey && !newkey)
...@@ -9139,17 +9210,21 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) { ...@@ -9139,17 +9210,21 @@ keyfetch_done(isc_task_t *task, isc_event_t *event) {
newkey = ISC_TRUE; newkey = ISC_TRUE;
if (initializing) { if (initializing) {
dns_keytag_t tag = 0;
CHECK(compute_tag(keyname, &dnskey,
mctx, &tag));
dns_zone_log(zone, ISC_LOG_WARNING, dns_zone_log(zone, ISC_LOG_WARNING,
"Initializing automatic trust " "Initializing automatic trust "
"anchor management for zone '%s'; " "anchor management for zone '%s'; "
"DNSKEY ID %d is now trusted, " "DNSKEY ID %d is now trusted, "
"waiving the normal 30-day " "waiving the normal 30-day "
"waiting period.", "waiting period.",
namebuf, tag); namebuf, keytag);
trustkey = ISC_TRUE; 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 { } else {
/* /*
...@@ -9380,6 +9455,16 @@ zone_refreshkeys(dns_zone_t *zone) { ...@@ -9380,6 +9455,16 @@ zone_refreshkeys(dns_zone_t *zone) {
dns_db_attach(db, &kfetch->db); dns_db_attach(db, &kfetch->db);
kfetch->fetch = NULL; 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, result = dns_resolver_createfetch(zone->view->resolver,
kname, dns_rdatatype_dnskey, kname, dns_rdatatype_dnskey,
NULL, NULL, NULL, NULL, NULL, NULL,
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment