Merge branch '714-dnssec-key-logging' into 'master'

Resolve "Add logging to DNSSEC key events"

Closes #714

See merge request isc-projects/bind9!1371

CHANGES

@@ -1,3 +1,11 @@
+5152.	[func]		Improved logging of DNSSEC key events:
+			- Zone signing and DNSKEY maintenance events are
+			  now logged to the "dnssec" category
+			- Messages are now logged when DNSSEC keys are
+			  pubished, activated, inactivated, deleted,
+			  or revoked.
+			[GL #714]
+
 5151.	[func]		Options that have been been marked as obsolete in
 			named.conf for a very long time are now fatal
 			configuration errors. [GL #358]

bin/tests/system/autosign/tests.sh

@@ -1467,5 +1467,20 @@ n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
 
+echo_i "checking key maintenance events were logged correctly ($n)"
+ret=0
+pub=`grep "DNSKEY .* is now published" ns1/named.run | wc -l`
+[ "$pub" -eq 6 ] || ret=1
+act=`grep "DNSKEY .* is now active" ns1/named.run | wc -l`
+[ "$act" -eq 5 ] || ret=1
+rev=`grep "DNSKEY .* is now revoked" ns1/named.run | wc -l`
+[ "$rev" -eq 1 ] || ret=1
+inac=`grep "DNSKEY .* is now inactive" ns1/named.run | wc -l`
+[ "$inac" -eq 1 ] || ret=1
+del=`grep "DNSKEY .* is now deleted" ns1/named.run | wc -l`
+[ "$del" -eq 1 ] || ret=1
+if [ $ret != 0 ]; then echo_i "failed"; fi
+status=`expr $status + $ret`
+
 echo_i "exit status: $status"
 [ $status -eq 0 ] || exit 1

doc/arm/notes.xml

@@ -597,6 +597,13 @@
 	  disables reading of the file <filename>$HOME/.digrc</filename>.
 	</para>
       </listitem>
+      <listitem>
+	<para>
+	  Zone signing and key maintenance events are now logged to the
+	  <command>dnssec</command> category rather than
+	  <command>zone</command>.
+	</para>
+      </listitem>
     </itemizedlist>
   </section>
 

lib/dns/dnssec.c

@@ -1818,23 +1818,20 @@ publish_key(dns_diff_t *diff, dns_dnsseckey_t *key, const dns_name_t *origin,
 	isc_result_t result;
 	dns_difftuple_t *tuple = NULL;
 	unsigned char buf[DST_KEY_MAXSIZE];
+	char keystr[DST_KEY_FORMATSIZE];
 	dns_rdata_t dnskey = DNS_RDATA_INIT;
-	char alg[80];
 
 	dns_rdata_reset(&dnskey);
 	RETERR(make_dnskey(key->key, buf, sizeof(buf), &dnskey));
+	dst_key_format(key->key, keystr, sizeof(keystr));
 
-	dns_secalg_format(dst_key_alg(key->key), alg, sizeof(alg));
-	report("Fetching %s %d/%s from key %s.",
-	       key->ksk ?  (allzsk ?  "KSK/ZSK" : "KSK") : "ZSK",
-	       dst_key_id(key->key), alg,
+	report("Fetching %s (%s) from key %s.",
+	       keystr, key->ksk ? (allzsk ? "KSK/ZSK" : "KSK") : "ZSK",
 	       key->source == dns_keysource_user ?  "file" : "repository");
 
 	if (key->prepublish && ttl > key->prepublish) {
-		char keystr[DST_KEY_FORMATSIZE];
 		isc_stdtime_t now;
 
-		dst_key_format(key->key, keystr, sizeof(keystr));
 		report("Key %s: Delaying activation to match the DNSKEY TTL.\n",
 		       keystr, ttl);
 
@@ -2048,9 +2045,11 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 	 */
 	for (key = ISC_LIST_HEAD(*keys);
 	     key != NULL;
-	     key = ISC_LIST_NEXT(key, link)) {
+	     key = ISC_LIST_NEXT(key, link))
+	{
 		if (key->source == dns_keysource_user &&
-		    (key->hint_publish || key->force_publish)) {
+		    (key->hint_publish || key->force_publish))
+		{
 			RETERR(publish_key(diff, key, origin, ttl,
 					   mctx, allzsk, report));
 		}
@@ -2069,15 +2068,19 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 
 		for (key = ISC_LIST_HEAD(*newkeys);
 		     key != NULL;
-		     key = ISC_LIST_NEXT(key, link)) {
+		     key = ISC_LIST_NEXT(key, link))
+		{
 			dns_ttl_t thisttl = dst_key_getttl(key->key);
 			if (thisttl != 0 &&
 			    (shortest == 0 || thisttl < shortest))
+			{
 				shortest = thisttl;
+			}
 		}
 
-		if (shortest != 0)
+		if (shortest != 0) {
 			ttl = shortest;
+		}
 	}
 
 	/*
@@ -2086,20 +2089,23 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 	 */
 	for (key1 = ISC_LIST_HEAD(*newkeys); key1 != NULL; key1 = next) {
 		bool key_revoked = false;
+		char keystr1[DST_KEY_FORMATSIZE];
+		char keystr2[DST_KEY_FORMATSIZE];
 
 		next = ISC_LIST_NEXT(key1, link);
 
 		for (key2 = ISC_LIST_HEAD(*keys);
 		     key2 != NULL;
-		     key2 = ISC_LIST_NEXT(key2, link)) {
+		     key2 = ISC_LIST_NEXT(key2, link))
+		{
 			int f1 = dst_key_flags(key1->key);
 			int f2 = dst_key_flags(key2->key);
 			int nr1 = f1 & ~DNS_KEYFLAG_REVOKE;
 			int nr2 = f2 & ~DNS_KEYFLAG_REVOKE;
 			if (nr1 == nr2 &&
 			    dst_key_alg(key1->key) == dst_key_alg(key2->key) &&
-			    dst_key_pubcompare(key1->key, key2->key,
-					       true)) {
+			    dst_key_pubcompare(key1->key, key2->key, true))
+			{
 				int r1, r2;
 				r1 = dst_key_flags(key1->key) &
 					DNS_KEYFLAG_REVOKE;
@@ -2110,33 +2116,68 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 			}
 		}
 
+		/* Printable version of key1 (the newly aquired key) */
+		dst_key_format(key1->key, keystr1, sizeof(keystr1));
+
 		/* No match found in keys; add the new key. */
 		if (key2 == NULL) {
 			ISC_LIST_UNLINK(*newkeys, key1, link);
 			ISC_LIST_APPEND(*keys, key1, link);
 
 			if (key1->source != dns_keysource_zoneapex &&
-			    (key1->hint_publish || key1->force_publish)) {
+			    (key1->hint_publish || key1->force_publish))
+			{
 				RETERR(publish_key(diff, key1, origin, ttl,
 						   mctx, allzsk, report));
-				if (key1->hint_sign || key1->force_sign)
+				isc_log_write(dns_lctx,
+					      DNS_LOGCATEGORY_DNSSEC,
+					      DNS_LOGMODULE_DNSSEC,
+					      ISC_LOG_INFO,
+					      "DNSKEY %s (%s) is now published",
+					      keystr1, key1->ksk ?
+					      (allzsk ? "KSK/ZSK" : "KSK") :
+					      "ZSK");
+				if (key1->hint_sign || key1->force_sign) {
 					key1->first_sign = true;
+					isc_log_write(dns_lctx,
+						      DNS_LOGCATEGORY_DNSSEC,
+						      DNS_LOGMODULE_DNSSEC,
+						      ISC_LOG_INFO,
+						      "DNSKEY %s (%s) is now "
+						      "active",
+						      keystr1, key1->ksk ?
+						      (allzsk ? "KSK/ZSK" :
+						       "KSK") : "ZSK");
+				}
 			}
 
 			continue;
 		}
 
+		/* Printable version of key2 (the old key, if any) */
+		dst_key_format(key2->key, keystr2, sizeof(keystr2));
+
 		/* Match found: remove or update it as needed */
 		if (key1->hint_remove) {
 			RETERR(remove_key(diff, key2, origin, ttl, mctx,
 					  "expired", report));
 			ISC_LIST_UNLINK(*keys, key2, link);
-			if (removed != NULL)
+
+			if (removed != NULL) {
 				ISC_LIST_APPEND(*removed, key2, link);
-			else
+				isc_log_write(dns_lctx,
+					      DNS_LOGCATEGORY_DNSSEC,
+					      DNS_LOGMODULE_DNSSEC,
+					      ISC_LOG_INFO,
+					      "DNSKEY %s (%s) is now deleted",
+					      keystr2, key2->ksk ? (allzsk ?
+					      "KSK/ZSK" : "KSK") : "ZSK");
+			} else {
 				dns_dnsseckey_destroy(mctx, &key2);
+			}
 		} else if (key_revoked &&
-			 (dst_key_flags(key1->key) & DNS_KEYFLAG_REVOKE) != 0) {
+			   (dst_key_flags(key1->key) & DNS_KEYFLAG_REVOKE) != 0)
+		{
 
 			/*
 			 * A previously valid key has been revoked.
@@ -2146,10 +2187,20 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 			RETERR(remove_key(diff, key2, origin, ttl, mctx,
 					  "revoked", report));
 			ISC_LIST_UNLINK(*keys, key2, link);
-			if (removed != NULL)
+			if (removed != NULL) {
 				ISC_LIST_APPEND(*removed, key2, link);
-			else
+				isc_log_write(dns_lctx,
+					      DNS_LOGCATEGORY_DNSSEC,
+					      DNS_LOGMODULE_DNSSEC,
+					      ISC_LOG_INFO,
+					      "DNSKEY %s (%s) is now revoked; "
+					      "new ID is %05d",
+					      keystr2, key2->ksk ? (allzsk ?
+					      "KSK/ZSK" : "KSK") : "ZSK",
+					      dst_key_id(key1->key));
+			} else {
 				dns_dnsseckey_destroy(mctx, &key2);
+			}
 
 			RETERR(publish_key(diff, key1, origin, ttl,
 					   mctx, allzsk, report));
@@ -2169,7 +2220,27 @@ dns_dnssec_updatekeys(dns_dnsseckeylist_t *keys, dns_dnsseckeylist_t *newkeys,
 		} else {
 			if (!key2->is_active &&
 			    (key1->hint_sign || key1->force_sign))
+			{
 				key2->first_sign = true;
+				isc_log_write(dns_lctx,
+					      DNS_LOGCATEGORY_DNSSEC,
+					      DNS_LOGMODULE_DNSSEC,
+					      ISC_LOG_INFO,
+					      "DNSKEY %s (%s) is now active",
+					      keystr1, key1->ksk ? (allzsk ?
+					      "KSK/ZSK" : "KSK") : "ZSK");
+			} else if (key2->is_active &&
+				   !key1->hint_sign && !key1->force_sign)
+			{
+				isc_log_write(dns_lctx,
+					      DNS_LOGCATEGORY_DNSSEC,
+					      DNS_LOGMODULE_DNSSEC,
+					      ISC_LOG_INFO,
+					      "DNSKEY %s (%s) is now inactive",
+					      keystr1, key1->ksk ? (allzsk ?
+					      "KSK/ZSK" : "KSK") : "ZSK");
+			}
+
 			key2->hint_sign = key1->hint_sign;
 			key2->hint_publish = key1->hint_publish;
 		}

lib/dns/include/dns/dnssec.h

@@ -49,22 +49,22 @@ typedef enum {
  */
 struct dns_dnsseckey {
 	dst_key_t *key;
-	bool hint_publish;  /*% metadata says to publish */
-	bool force_publish; /*% publish regardless of metadata */
-	bool hint_sign;     /*% metadata says to sign with this key */
-	bool force_sign;    /*% sign with key regardless of metadata */
-	bool hint_remove;   /*% metadata says *don't* publish */
-	bool is_active;     /*% key is already active */
-	bool first_sign;    /*% key is newly becoming active */
-	unsigned int prepublish;     /*% how long until active? */
-	dns_keysource_t source;      /*% how the key was found */
-	bool ksk;           /*% this is a key-signing key */
-	bool legacy;        /*% this is old-style key with no
-					 metadata (possibly generated by
-					 an older version of BIND9) and
-					 should be ignored when searching
-					 for keys to import into the zone */
-	unsigned int index;          /*% position in list */
+	bool hint_publish;  	  /*% metadata says to publish */
+	bool force_publish; 	  /*% publish regardless of metadata */
+	bool hint_sign;     	  /*% metadata says to sign with this key */
+	bool force_sign;    	  /*% sign with key regardless of metadata */
+	bool hint_remove;   	  /*% metadata says *don't* publish */
+	bool is_active;     	  /*% key is already active */
+	bool first_sign;    	  /*% key is newly becoming active */
+	unsigned int prepublish;  /*% how long until active? */
+	dns_keysource_t source;   /*% how the key was found */
+	bool ksk;           	  /*% this is a key-signing key */
+	bool legacy;        	  /*% this is old-style key with no
+				      metadata (possibly generated by
+				      an older version of BIND9) and
+				      should be ignored when searching
+				      for keys to import into the zone */
+	unsigned int index;       /*% position in list */
 	ISC_LINK(dns_dnsseckey_t) link;
 };