kasp tests: fix wait for reconfig done

The wait until zones are signed after rndc reconfig is broken because the zones are already signed before the reconfig. Fix by having a different way to ensure the signing of the zone is complete. This does require a call to the "wait_for_done_signing" function after each "check_keys" call after the ns6 reconfig. The "wait_for_done_signing" looks for a (newly added) debug log message that named will output if it is done signing with a certain key.
2020-05-26 13:28:29 +02:00
parent cf76d839ae
commit a47192ed5b
4 changed files with 68 additions and 69 deletions
--- a/bin/tests/system/kasp/clean.sh
+++ b/bin/tests/system/kasp/clean.sh
@@ -22,6 +22,6 @@ rm -f ns*/dsset-* ns*/*.db ns*/*.db.signed
 rm -f ns*/keygen.out.* ns*/settime.out.* ns*/signer.out.*
 rm -f ns*/managed-keys.bind
 rm -f ns*/*.mkeys
-rm -f ns*/zones* ns*/*.db.infile
+rm -f ns*/zones ns*/*.db.infile
 rm -f *.created published.test* retired.test*
 rm -f python.out.*
--- a/bin/tests/system/kasp/ns6/setup.sh
+++ b/bin/tests/system/kasp/ns6/setup.sh
@@ -19,7 +19,6 @@ setup() {
 	echo_i "setting up zone: $zone"
 	zonefile="${zone}.db"
 	infile="${zone}.db.infile"
-	echo "$zone" >> zones.2
 }

 private_type_record() {
@@ -47,8 +46,8 @@ zsktimes="-P now -A now"
 KSK=$($KEYGEN -a ECDSAP256SHA256 -L 7200 -f KSK $ksktimes $zone 2> keygen.out.$zone.1)
 ZSK=$($KEYGEN -a ECDSAP256SHA256 -L 7200        $zsktimes $zone 2> keygen.out.$zone.2)
 cat template.db.in "${KSK}.key" "${ZSK}.key" > "$infile"
-private_type_record $zone 5 "$KSK" >> "$infile"
-private_type_record $zone 5 "$ZSK" >> "$infile"
+private_type_record $zone 13 "$KSK" >> "$infile"
+private_type_record $zone 13 "$ZSK" >> "$infile"
 $SIGNER -S -x -s now-1h -e now+2w -o $zone -O full -f $zonefile $infile > signer.out.$zone.1 2>&1

 # Set up a zone with auto-dnssec maintain to migrate to dnssec-policy, but this
--- a/bin/tests/system/kasp/tests.sh
+++ b/bin/tests/system/kasp/tests.sh
@@ -1062,7 +1062,6 @@ check_apex() {
 	dig_with_opts "$ZONE" "@${SERVER}" $_qtype > "dig.out.$DIR.test$n" || log_error "dig ${ZONE} ${_qtype} failed"
 	grep "status: NOERROR" "dig.out.$DIR.test$n" > /dev/null || log_error "mismatch status in DNS response"

-
 	if [ "$(key_get KEY1 STATE_DNSKEY)" = "rumoured" ] || [ "$(key_get KEY1 STATE_DNSKEY)" = "omnipresent" ]; then
 		grep "${ZONE}\..*${DNSKEY_TTL}.*IN.*${_qtype}.*257.*.3.*$(key_get KEY1 ALG_NUM)" "dig.out.$DIR.test$n" > /dev/null || log_error "missing ${_qtype} record in response for key $(key_get KEY1 ID)"
 		check_signatures $_qtype "dig.out.$DIR.test$n" "KSK"
@@ -2298,7 +2297,6 @@ set_addkeytime  "KEY1" "SYNCPUBLISH" "${created}" 43800
 # Key lifetime is unlimited, so not setting RETIRED and REMOVED.

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2350,7 +2348,6 @@ set_addkeytime  "KEY1" "ACTIVE"      "${created}" -900
 set_addkeytime  "KEY1" "SYNCPUBLISH" "${created}" 43800

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2379,7 +2376,6 @@ set_addkeytime  "KEY1" "ACTIVE"      "${created}" -44700
 set_keytime     "KEY1" "SYNCPUBLISH" "${created}"

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2407,7 +2403,6 @@ set_addkeytime  "KEY1" "ACTIVE"      "${created}" -143100
 set_addkeytime  "KEY1" "SYNCPUBLISH" "${created}" -98400

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2496,7 +2491,6 @@ check_keys
 # These keys are immediately published and activated.
 rollover_predecessor_keytimes 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2540,7 +2534,6 @@ IpubZSK=93600
 set_addkeytime "KEY3" "ACTIVE" "${created}" "${IpubZSK}"
 set_retired_removed "KEY3" "${Lzsk}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2574,7 +2567,6 @@ set_addkeytime "KEY3" "PUBLISHED"   "${created}" -93600
 set_keytime    "KEY3" "ACTIVE"      "${created}"
 set_retired_removed "KEY3" "${Lzsk}" "${IretZSK}"
 check_keytimes
-
 check_apex
 # Subdomain still has good signatures of ZSK (KEY2).
 # Set expected zone signing on for KEY2 and off for KEY3,
@@ -2617,7 +2609,6 @@ published=$(key_get KEY3 PUBLISHED)
 set_addkeytime "KEY3" "ACTIVE"      "${published}" "${IpubZSK}"
 set_retired_removed "KEY3" "${Lzsk}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2647,7 +2638,6 @@ published=$(key_get KEY3 PUBLISHED)
 set_addkeytime "KEY3" "ACTIVE"      "${published}" "${IpubZSK}"
 set_retired_removed "KEY3" "${Lzsk}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2711,7 +2701,6 @@ check_keys
 # These keys are immediately published and activated.
 rollover_predecessor_keytimes 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2764,7 +2753,6 @@ syncpub=$(key_get KEY3 SYNCPUBLISH)
 set_addkeytime "KEY3" "ACTIVE"      "${syncpub}" "${Dreg}"
 set_retired_removed "KEY3" "${Lksk}" "${IretKSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2801,7 +2789,6 @@ syncpub=$(key_get KEY3 SYNCPUBLISH)
 set_addkeytime "KEY3" "ACTIVE"      "${syncpub}" "${Dreg}"
 set_retired_removed "KEY3" "${Lksk}" "${IretKSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2842,7 +2829,6 @@ syncpub=$(key_get KEY3 SYNCPUBLISH)
 set_addkeytime "KEY3" "ACTIVE"      "${syncpub}"    "${Dreg}"
 set_retired_removed "KEY3" "${Lksk}" "${IretKSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2875,7 +2861,6 @@ syncpub=$(key_get KEY3 SYNCPUBLISH)
 set_addkeytime "KEY3" "ACTIVE"      "${syncpub}"   "${Dreg}"
 set_retired_removed "KEY3" "${Lksk}" "${IretKSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2941,7 +2926,6 @@ check_keys
 # This key is immediately published and activated.
 csk_rollover_predecessor_keytimes 0 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -2988,7 +2972,6 @@ set_addkeytime "KEY2" "SYNCPUBLISH" "${created}" "${Ipub}"
 set_addkeytime "KEY2" "ACTIVE"      "${created}" "${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3030,7 +3013,6 @@ set_keytime    "KEY2" "SYNCPUBLISH" "${created}"
 set_keytime    "KEY2" "ACTIVE"      "${created}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 # Subdomain still has good signatures of old CSK (KEY1).
 # Set expected zone signing on for KEY1 and off for KEY2,
@@ -3079,7 +3061,6 @@ syncpub=$(key_get KEY2 SYNCPUBLISH)
 set_addkeytime "KEY2" "PUBLISHED"   "${syncpub}" "-${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3111,7 +3092,6 @@ syncpub=$(key_get KEY2 SYNCPUBLISH)
 set_addkeytime "KEY2" "PUBLISHED"   "${syncpub}" "-${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3149,7 +3129,6 @@ syncpub=$(key_get KEY2 SYNCPUBLISH)
 set_addkeytime "KEY2" "PUBLISHED"   "${syncpub}" "-${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3181,7 +3160,6 @@ syncpub=$(key_get KEY2 SYNCPUBLISH)
 set_addkeytime "KEY2" "PUBLISHED"   "${syncpub}" "-${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3240,7 +3218,6 @@ check_keys
 # This key is immediately published and activated.
 csk_rollover_predecessor_keytimes 0 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3327,7 +3304,6 @@ set_keytime    "KEY2" "SYNCPUBLISH" "${created}"
 set_keytime    "KEY2" "ACTIVE"      "${created}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 # Subdomain still has good signatures of old CSK (KEY1).
 # Set expected zone signing on for KEY1 and off for KEY2,
@@ -3373,7 +3349,6 @@ set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" "${Ipub}"
 set_addkeytime "KEY2" "ACTIVE"      "${published}" "${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3414,7 +3389,6 @@ set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" "${Ipub}"
 set_addkeytime "KEY2" "ACTIVE"      "${published}" "${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3447,7 +3421,6 @@ set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" "${Ipub}"
 set_addkeytime "KEY2" "ACTIVE"      "${published}" "${Ipub}"
 set_retired_removed "KEY2" "${Lcsk}" "${IretCSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3504,7 +3477,6 @@ IretKSK=0
 IretZSK=0
 rollover_predecessor_keytimes 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3544,7 +3516,6 @@ Lcsk=0
 IretCSK=0
 csk_rollover_predecessor_keytimes 0 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3598,7 +3569,6 @@ check_keys
 # These keys are immediately published and activated.
 rollover_predecessor_keytimes 0
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3661,7 +3631,6 @@ created=$(key_get KEY2 CREATED)
 set_addkeytime "KEY2" "PUBLISHED"   "${created}" -43200
 set_addkeytime "KEY2" "ACTIVE"      "${created}" -43200
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3724,7 +3693,6 @@ created=$(key_get KEY2 CREATED)
 set_addkeytime "KEY2" "PUBLISHED"   "${created}" -43200
 set_addkeytime "KEY2" "ACTIVE"      "${created}" -43200
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3744,24 +3712,43 @@ now="$(TZ=UTC date +%s)"
 time_passed=$((now-start_time))
 echo_i "${time_passed} seconds passed between start of tests and reconfig"

-# The NSEC record at the apex of the zone and its RRSIG records are
-# added as part of the last step in signing a zone.  We wait for the
-# NSEC records to appear before proceeding with a counter to prevent
-# infinite loops if there is a error. Make sure the zone is signed
-# with the new algorithm.
-_wait_for_done_reconfig() {
-	while read -r zone
-	do
-		dig_with_opts "$zone" @10.53.0.6 nsec > "dig.out.ns6.test$n.$zone" || return 1
-		grep "NS SOA" "dig.out.ns6.test$n.$zone" > /dev/null || return 1
-		grep "$zone\..*IN.*RRSIG.*NSEC" "dig.out.ns6.test$n.$zone" > /dev/null || return 1
-	done < ns6/zones.2
-}
-retry_quiet 30 _wait_for_done_reconfig || ret=1
-test "$ret" -eq 0 || echo_i "failed"
-status=$((status+ret))
+# Wait until we have seen "zone_rekey done:" message for this key.
+_wait_for_done_signing() {
+	_zone=$1

-next_key_event_threshold=$((next_key_event_threshold+i))
+	_ksk=$(key_get $2 KSK)
+	_zsk=$(key_get $2 ZSK)
+	if [ "$_ksk" = "yes" ]; then
+		_role="KSK"
+		_expect_type=EXPECT_KRRSIG
+	elif [ "$_zsk" = "yes" ]; then
+		_role="ZSK"
+		_expect_type=EXPECT_ZRRSIG
+	fi
+
+	if [ "$(key_get ${2} $_expect_type)" = "yes" ] && [ "$(key_get $2 $_role)" = "yes" ]; then
+		_keyid=$(key_get $2 ID)
+		_keyalg=$(key_get $2 ALG_STR)
+		echo_i "wait for zone ${_zone} is done signing with $2 ${_zone}/${_keyalg}/${_keyid}"
+		grep "zone_rekey done: key ${_keyid}/${_keyalg}" "${DIR}/named.run" > /dev/null || return 1
+	fi
+
+	return 0
+}
+
+wait_for_done_signing() {
+	n=$((n+1))
+	echo_i "wait for zone ${ZONE} is done signing ($n)"
+	ret=0
+
+	retry_quiet 30 _wait_for_done_signing ${ZONE} KEY1 || ret=1
+	retry_quiet 30 _wait_for_done_signing ${ZONE} KEY2 || ret=1
+	retry_quiet 30 _wait_for_done_signing ${ZONE} KEY3 || ret=1
+	retry_quiet 30 _wait_for_done_signing ${ZONE} KEY4 || ret=1
+
+	test "$ret" -eq 0 || echo_i "failed"
+	status=$((status+ret))
+}

 #
 # Testing migration.
@@ -3777,6 +3764,7 @@ key_set     "KEY1" "LEGACY"  "no"
 key_set     "KEY2" "LEGACY"  "no"

 check_keys
+wait_for_done_signing

 rollover_predecessor_keytimes 0
 # Key now has lifetime of 60 days (5184000 seconds).
@@ -3793,7 +3781,6 @@ set_addkeytime "KEY2" "RETIRED"     "${active}"  "${Lzsk}"
 retired=$(key_get KEY2 RETIRED)
 set_addkeytime "KEY2" "REMOVED"     "${retired}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3843,6 +3830,7 @@ set_keystate "KEY4" "STATE_DNSKEY" "rumoured"
 set_keystate "KEY4" "STATE_ZRRSIG" "rumoured"

 check_keys
+wait_for_done_signing

 # KSK must be retired since it no longer matches the policy.
 # -P     : now-3900s
@@ -3908,7 +3896,6 @@ set_addkeytime "KEY4" "RETIRED"     "${active}"  "${Lzsk}"
 retired=$(key_get KEY4 RETIRED)
 set_addkeytime "KEY4" "REMOVED"     "${retired}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -3959,6 +3946,7 @@ set_keystate "KEY4" "STATE_DNSKEY" "rumoured"
 set_keystate "KEY4" "STATE_ZRRSIG" "hidden"

 check_keys
+wait_for_done_signing

 # KSK must be retired since it no longer matches the policy.
 # -P     : now-3900s
@@ -4024,7 +4012,6 @@ set_addkeytime "KEY4" "RETIRED"     "${active}"  "${Lzsk}"
 retired=$(key_get KEY4 RETIRED)
 set_addkeytime "KEY4" "REMOVED"     "${retired}" "${IretZSK}"
 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4100,6 +4087,7 @@ set_keystate "KEY4" "STATE_DNSKEY" "rumoured"
 set_keystate "KEY4" "STATE_ZRRSIG" "rumoured"

 check_keys
+wait_for_done_signing

 # The old keys are published and activated.
 rollover_predecessor_keytimes 0
@@ -4152,7 +4140,6 @@ set_keytime    "KEY4" "PUBLISHED"   "${created}"
 set_keytime    "KEY4" "ACTIVE"      "${created}"

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4179,6 +4166,7 @@ set_keystate "KEY3" "STATE_KRRSIG" "omnipresent"
 set_keystate "KEY4" "STATE_DNSKEY" "omnipresent"

 check_keys
+wait_for_done_signing

 # The old keys were activated three hours ago (10800 seconds).
 rollover_predecessor_keytimes -10800
@@ -4205,7 +4193,6 @@ set_addkeytime "KEY4" "PUBLISHED"   "${created}"   -10800
 set_addkeytime "KEY4" "ACTIVE"      "${created}"   -10800

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4234,6 +4221,7 @@ set_keystate "KEY3" "STATE_DS"     "rumoured"
 set_keystate "KEY4" "STATE_ZRRSIG" "omnipresent"

 check_keys
+wait_for_done_signing

 # The old keys were activated 9 hours ago (32400 seconds)
 # and retired 6 hours ago (21600 seconds).
@@ -4261,7 +4249,6 @@ set_addkeytime "KEY4" "PUBLISHED"   "${created}"   -32400
 set_addkeytime "KEY4" "ACTIVE"      "${created}"   -32400

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4291,6 +4278,7 @@ set_keystate     "KEY2" "STATE_ZRRSIG" "unretentive"
 set_keystate     "KEY3" "STATE_DS"     "omnipresent"

 check_keys
+wait_for_done_signing

 # The old keys were activated 38 hours ago (136800 seconds)
 # and retired 35 hours ago (126000 seconds).
@@ -4318,7 +4306,6 @@ set_addkeytime "KEY4" "PUBLISHED"   "${created}"   -136800
 set_addkeytime "KEY4" "ACTIVE"      "${created}"   -136800

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4339,6 +4326,7 @@ set_keystate "KEY1" "STATE_KRRSIG" "hidden"
 set_keystate "KEY2" "STATE_DNSKEY" "hidden"

 check_keys
+wait_for_done_signing

 # The old keys were activated 40 hours ago (144000 seconds)
 # and retired 35 hours ago (133200 seconds).
@@ -4366,7 +4354,6 @@ set_addkeytime "KEY4" "PUBLISHED"   "${created}"   -144000
 set_addkeytime "KEY4" "ACTIVE"      "${created}"   -144000

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4390,6 +4377,7 @@ set_server "ns6" "10.53.0.6"
 set_keystate "KEY2" "STATE_ZRRSIG" "hidden"

 check_keys
+wait_for_done_signing

 # The old keys were activated 47 hours ago (169200 seconds)
 # and retired 34 hours ago (158400 seconds).
@@ -4417,7 +4405,6 @@ set_addkeytime "KEY4" "PUBLISHED"   "${created}"   -169200
 set_addkeytime "KEY4" "ACTIVE"      "${created}"   -169200

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4470,6 +4457,7 @@ set_keystate "KEY2" "STATE_ZRRSIG" "rumoured"
 set_keystate "KEY2" "STATE_DS"     "hidden"

 check_keys
+wait_for_done_signing

 # CSK must be retired since it no longer matches the policy.
 csk_rollover_predecessor_keytimes 0 0
@@ -4501,7 +4489,6 @@ Ipub=28800
 set_addkeytime "KEY2" "SYNCPUBLISH" "${created}" "${Ipub}"

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4527,6 +4514,7 @@ set_keystate "KEY2" "STATE_DNSKEY" "omnipresent"
 set_keystate "KEY2" "STATE_KRRSIG" "omnipresent"

 check_keys
+wait_for_done_signing

 # The old key was activated three hours ago (10800 seconds).
 csk_rollover_predecessor_keytimes -10800 -10800
@@ -4544,7 +4532,6 @@ published=$(key_get KEY2 PUBLISHED)
 set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" "${Ipub}"

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4573,6 +4560,7 @@ set_keystate "KEY2" "STATE_ZRRSIG" "omnipresent"
 set_keystate "KEY2" "STATE_DS"     "rumoured"

 check_keys
+wait_for_done_signing

 # The old key was activated 9 hours ago (10800 seconds)
 # and retired 6 hours ago (21600 seconds).
@@ -4590,7 +4578,6 @@ published=$(key_get KEY2 PUBLISHED)
 set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" "${Ipub}"

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4617,6 +4604,7 @@ set_keystate     "KEY1" "STATE_DS"     "hidden"
 set_keystate     "KEY2" "STATE_DS"     "omnipresent"

 check_keys
+wait_for_done_signing

 # The old key was activated 38 hours ago (136800 seconds)
 # and retired 35 hours ago (126000 seconds).
@@ -4634,7 +4622,6 @@ published=$(key_get KEY2 PUBLISHED)
 set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" ${Ipub}

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4654,6 +4641,7 @@ set_keystate "KEY1" "STATE_DNSKEY" "hidden"
 set_keystate "KEY1" "STATE_KRRSIG" "hidden"

 check_keys
+wait_for_done_signing

 # The old key was activated 40 hours ago (144000 seconds)
 # and retired 37 hours ago (133200 seconds).
@@ -4671,7 +4659,6 @@ published=$(key_get KEY2 PUBLISHED)
 set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" ${Ipub}

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
@@ -4695,6 +4682,7 @@ set_server "ns6" "10.53.0.6"
 set_keystate "KEY1" "STATE_ZRRSIG" "hidden"

 check_keys
+wait_for_done_signing

 # The old keys were activated 47 hours ago (169200 seconds)
 # and retired 44 hours ago (158400 seconds).
@@ -4712,7 +4700,6 @@ published=$(key_get KEY2 PUBLISHED)
 set_addkeytime "KEY2" "SYNCPUBLISH" "${published}" ${Ipub}

 check_keytimes
-
 check_apex
 check_subdomain
 dnssec_verify
--- a/lib/dns/zone.c
+++ b/lib/dns/zone.c
@@ -19591,7 +19591,7 @@ zone_rekey(dns_zone_t *zone) {

 		/*
 		 * Clear fullsign flag, if it was set, so we don't do
-		 * another full signing next time
+		 * another full signing next time.
 		 */
 		DNS_ZONEKEY_CLROPTION(zone, DNS_ZONEKEY_FULLSIGN);

@@ -19709,6 +19709,19 @@ zone_rekey(dns_zone_t *zone) {
 	}
 	UNLOCK_ZONE(zone);

+	if (isc_log_wouldlog(dns_lctx, ISC_LOG_DEBUG(3))) {
+		for (key = ISC_LIST_HEAD(dnskeys); key != NULL;
+		     key = ISC_LIST_NEXT(key, link)) {
+			/* This debug log is used in the kasp system test */
+			char algbuf[DNS_SECALG_FORMATSIZE];
+			dns_secalg_format(dst_key_alg(key->key), algbuf,
+					  sizeof(algbuf));
+			dnssec_log(zone, ISC_LOG_DEBUG(3),
+				   "zone_rekey done: key %d/%s",
+				   dst_key_id(key->key), algbuf);
+		}
+	}
+
 	result = ISC_R_SUCCESS;

 failure: