From d8de28610d4a2a40f0687fb9ac2de4aab5950ae1 Mon Sep 17 00:00:00 2001
From: Matthijs Mekking <matthijs@isc.org>
Date: Fri, 19 Apr 2019 11:38:24 +0200
Subject: [PATCH 1/3] Remove sleeps

Remove sleep calls from test, rely on wait_for_log().  Make
wait_for_log() and dnssec_loadkeys_on() fail the test if the
appropriate log line is not found.

Slightly adjust the echo_i() lines to print only the key ID (not the
key name).

(cherry picked from commit 67f0635f3cdfbdd53f0bf18b9b8a3c93d0802efd)
---
 bin/tests/system/dnssec/tests.sh | 63 ++++++++++++++++++++------------
 1 file changed, 40 insertions(+), 23 deletions(-)

diff --git a/bin/tests/system/dnssec/tests.sh b/bin/tests/system/dnssec/tests.sh
index 6ce7abd3db..e799d425ca 100644
--- a/bin/tests/system/dnssec/tests.sh
+++ b/bin/tests/system/dnssec/tests.sh
@@ -27,6 +27,7 @@ RNDCCMD="$RNDC -c $SYSTEMTESTTOP/common/rndc.conf -p ${CONTROLPORT} -s"
 wait_for_log() {
         msg=$1
         file=$2
+
         for i in 1 2 3 4 5 6 7 8 9 10; do
                 nextpart "$file" | grep "$msg" > /dev/null && return
                 sleep 1
@@ -3673,29 +3674,33 @@ test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))
 
 # Roll the ZSK.
-echo_i "roll ZSK for zone $zone"
-sleep 1
 zsk2=`$KEYGEN -q -r $RANDFILE -a RSASHA1 -b 1024 -K ns2 -n zone $zone`
-echo_i "new ZSK $zsk2 created for zone $zone"
 echo "$zsk2" | sed -e 's/.*[+]//' -e 's/^0*//' > ns2/$zone.zsk.id2
 ZSK_ID2=`cat ns2/$zone.zsk.id2`
-dnssec_loadkeys_on 2 $zone
+
+echo_i "load new ZSK $ZSK_ID2 for $zone ($n)"
+ret=0
+dnssec_loadkeys_on 2 $zone || ret=1
+n=$((n+1))
+test "$ret" -eq 0 || echo_i "failed"
+status=$((status+ret))
 
 # Wait until new ZSK becomes active.
-sleep 1
-echo_i "make ZSK $ZSK inactive and make new ZSK $zsk2 active for zone $zone"
+echo_i "make ZSK $ZSK_ID inactive and make new ZSK $ZSK_ID2 active for zone $zone ($n)"
+ret=0
 $SETTIME -I now -K ns2 $ZSK > /dev/null
 $SETTIME -A now -K ns2 $zsk2 > /dev/null
-dnssec_loadkeys_on 2 $zone
+dnssec_loadkeys_on 2 $zone || ret=1
+n=$((n+1))
+test "$ret" -eq 0 || echo_i "failed"
+status=$((status+ret))
 
 # Remove the KSK from disk.
-sleep 1
-echo_i "remove the KSK $KSK for zone $zone from disk"
+echo_i "remove the KSK $KSK_ID for zone $zone from disk"
 mv ns2/$KSK.key ns2/$KSK.key.bak
 mv ns2/$KSK.private ns2/$KSK.private.bak
 
 # Update the zone that requires a resign of the SOA RRset.
-sleep 1
 echo_i "update the zone with $zone IN TXT nsupdate added me"
 (
 echo zone $zone
@@ -3733,35 +3738,38 @@ do
 done
 
 # Put back the KSK.
-sleep 1
-echo_i "put back the KSK $KSK for zone $zone from disk"
+echo_i "put back the KSK $KSK_ID for zone $zone from disk"
 mv ns2/$KSK.key.bak ns2/$KSK.key
 mv ns2/$KSK.private.bak ns2/$KSK.private
 
 # Roll the ZSK again.
-sleep 1
 zsk3=`$KEYGEN -q  -r $RANDFILE -a RSASHA1 -b 1024 -K ns2 -n zone $zone`
-echo_i "new ZSK $zsk3 created for zone $zone"
 echo "$zsk3" | sed -e 's/.*[+]//' -e 's/^0*//' > ns2/$zone.zsk.id3
 ZSK_ID3=`cat ns2/$zone.zsk.id3`
-dnssec_loadkeys_on 2 $zone
+
+echo_i "load new ZSK $ZSK_ID3 for $zone ($n)"
+ret=0
+dnssec_loadkeys_on 2 $zone || ret=1
+n=$((n+1))
+test "$ret" -eq 0 || echo_i "failed"
+status=$((status+ret))
 
 # Wait until new ZSK becomes active.
-sleep 1
-echo_i "delete old ZSK $ZSK make ZSK $ZSK2 inactive and make new ZSK $zsk3 active for zone $zone"
+echo_i "delete old ZSK $ZSK_ID make ZSK $ZSK_ID2 inactive and make new ZSK $ZSK_ID3 active for zone $zone ($n)"
 $SETTIME -D now -K ns2 $ZSK > /dev/null
 $SETTIME -I +5 -K ns2 $zsk2 > /dev/null
 $SETTIME -A +5 -K ns2 $zsk3 > /dev/null
-dnssec_loadkeys_on 2 $zone
+dnssec_loadkeys_on 2 $zone || ret=1
+n=$((n+1))
+test "$ret" -eq 0 || echo_i "failed"
+status=$((status+ret))
 
 # Remove the KSK from disk.
-sleep 1
-echo_i "remove the KSK $KSK for zone $zone from disk"
+echo_i "remove the KSK $KSK_ID for zone $zone from disk"
 mv ns2/$KSK.key ns2/$KSK.key.bak
 mv ns2/$KSK.private ns2/$KSK.private.bak
 
 # Update the zone that requires a resign of the SOA RRset.
-sleep 1
 echo_i "update the zone with $zone IN TXT nsupdate added me again"
 (
 echo zone $zone
@@ -3801,8 +3809,17 @@ do
 done
 
 # Wait for newest ZSK to become active.
-echo_i "sleep 6 to make new ZSK $zsk3 active and ZSK $zsk2 inactive"
-sleep 6
+echo_i "wait until new ZSK $ZSK_ID3 active and ZSK $ZSK_ID2 inactive"
+for i in 1 2 3 4 5 6 7 8 9 10; do
+    ret=0
+    grep "DNSKEY $zone/$DEFAULT_ALGORITHM/$ZSK_ID3 (ZSK) is now active" ns2/named.run > /dev/null || ret=1
+    grep "DNSKEY $zone/$DEFAULT_ALGORITHM/$ZSK_ID2 (ZSK) is now inactive" ns2/named.run > /dev/null || ret=1
+    [ "$ret" -eq 0 ] && break
+    sleep 1
+done
+n=$((n+1))
+test "$ret" -eq 0 || echo_i "failed"
+status=$((status+ret))
 
 # Redo the tests one more time.
 echo_i "checking DNSKEY RRset is signed with KSK only, new ZSK active (update-check-ksk, dnssec-ksk-only) ($n)"

From 9c77cd830662ffbd159e0eeb915762c932adebdd Mon Sep 17 00:00:00 2001
From: Matthijs Mekking <matthijs@isc.org>
Date: Fri, 19 Apr 2019 11:52:19 +0200
Subject: [PATCH 2/3] Harden grep key ID calls

Key IDs may accidentally match dig output that is not the key ID (for
example the RRSIG inception or expiration time, the query ID, ...).
Search for key ID + signer name should prevent that, as that is what
only should occur in the RRSIG record, and signer name always follows
the key ID.

(cherry picked from commit 83473b975830bd30b6f78b4a332585da37e6a8d3)
---
 bin/tests/system/dnssec/tests.sh | 67 ++++++++++++++++++--------------
 1 file changed, 38 insertions(+), 29 deletions(-)

diff --git a/bin/tests/system/dnssec/tests.sh b/bin/tests/system/dnssec/tests.sh
index e799d425ca..a93526d3d1 100644
--- a/bin/tests/system/dnssec/tests.sh
+++ b/bin/tests/system/dnssec/tests.sh
@@ -3650,14 +3650,23 @@ ZSK_ID=`cat ns2/${zone}.zsk.id`
 SECTIONS="+answer +noauthority +noadditional"
 echo_i "testing zone $zone KSK=$KSK_ID ZSK=$ZSK_ID"
 
+# Print IDs of keys used for generating RRSIG records for RRsets of type $1
+# found in dig output file $2.
+get_keys_which_signed() {
+	qtype=$1
+	output=$2
+	# The key ID is the 11th column of the RRSIG record line.
+	awk -v qt="$qtype" '$4 == "RRSIG" && $5 == qt {print $11}' < "$output"
+}
+
 # Basic checks to make sure everything is fine before the KSK is made offline.
 echo_i "checking DNSKEY RRset is signed with KSK only (update-check-ksk, dnssec-ksk-only) ($n)"
 ret=0
 $DIG $DIGOPTS $SECTIONS @10.53.0.2 DNSKEY $zone > dig.out.test$n
-lines=$(awk '$4 == "RRSIG" && $5 == "DNSKEY" {print}' dig.out.test$n | wc -l)
+lines=$(get_keys_which_signed "DNSKEY" dig.out.test$n | wc -l)
 test "$lines" -eq 1 || ret=1
-grep $KSK_ID dig.out.test$n > /dev/null || ret=1
-grep $ZSK_ID dig.out.test$n > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$KSK_ID$" > /dev/null || ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
 n=$((n+1))
 test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))
@@ -3665,10 +3674,10 @@ status=$((status+ret))
 echo_i "checking SOA RRset is signed with ZSK only (update-check-ksk, dnssec-ksk-only) ($n)"
 ret=0
 $DIG $DIGOPTS $SECTIONS @10.53.0.2 soa $zone > dig.out.test$n
-lines=$(awk '$4 == "RRSIG" && $5 == "SOA" {print}' dig.out.test$n | wc -l)
-grep $KSK_ID dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID dig.out.test$n > /dev/null || ret=1
+lines=$(get_keys_which_signed "SOA" dig.out.test$n | wc -l)
 test "$lines" -eq 1 || ret=1
+get_keys_which_signed "SOA" dig.out.test$n | grep "^$KSK_ID$" > /dev/null && ret=1
+get_keys_which_signed "SOA" dig.out.test$n | grep "^$ZSK_ID$" > /dev/null || ret=1
 n=$((n+1))
 test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))
@@ -3713,11 +3722,11 @@ echo send
 echo_i "checking DNSKEY RRset is signed with KSK only, KSK offline (update-check-ksk, dnssec-ksk-only) ($n)"
 ret=0
 $DIG $DIGOPTS $SECTIONS @10.53.0.2 DNSKEY $zone > dig.out.test$n
-lines=$(awk '$4 == "RRSIG" && $5 == "DNSKEY" {print}' dig.out.test$n | wc -l)
+lines=$(get_keys_which_signed "DNSKEY" dig.out.test$n | wc -l)
 test "$lines" -eq 1 || ret=1
-grep $KSK_ID  dig.out.test$n > /dev/null || ret=1
-grep $ZSK_ID  dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID2 dig.out.test$n > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$KSK_ID$" > /dev/null || ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID2$" > /dev/null && ret=1
 n=$((n+1))
 test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))
@@ -3727,11 +3736,11 @@ do
   echo_i "checking $qtype RRset is signed with ZSK only, KSK offline (update-check-ksk and dnssec-ksk-only) ($n)"
   ret=0
   $DIG $DIGOPTS $SECTIONS @10.53.0.2 $qtype $zone > dig.out.test$n
-  lines=$(awk -v qt="$qtype" '$4 == "RRSIG" && $5 == qt {print}' dig.out.test$n | wc -l)
-  grep $KSK_ID  dig.out.test$n > /dev/null && ret=1
-  grep $ZSK_ID  dig.out.test$n > /dev/null && ret=1
-  grep $ZSK_ID2 dig.out.test$n > /dev/null || ret=1
+  lines=$(get_keys_which_signed $qtype dig.out.test$n | wc -l)
   test "$lines" -eq 1 || ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$KSK_ID$" > /dev/null && ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$ZSK_ID2$" > /dev/null || ret=1
   n=$((n+1))
   test "$ret" -eq 0 || echo_i "failed"
   status=$((status+ret))
@@ -3782,12 +3791,12 @@ echo send
 echo_i "checking DNSKEY RRset is signed with KSK only, old ZSK deleted (update-check-ksk, dnssec-ksk-only) ($n)"
 ret=0
 $DIG $DIGOPTS $SECTIONS @10.53.0.2 DNSKEY $zone > dig.out.test$n
-lines=$(awk '$4 == "RRSIG" && $5 == "DNSKEY" {print}' dig.out.test$n | wc -l)
+lines=$(get_keys_which_signed "DNSKEY" dig.out.test$n | wc -l)
 test "$lines" -eq 1 || ret=1
-grep $KSK_ID  dig.out.test$n > /dev/null || ret=1
-grep $ZSK_ID  dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID2 dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID3 dig.out.test$n > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$KSK_ID$" > /dev/null || ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID2$" > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID3$" > /dev/null && ret=1
 n=$((n+1))
 test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))
@@ -3797,12 +3806,12 @@ do
   echo_i "checking $qtype RRset is signed with ZSK only, old ZSK deleted (update-check-ksk and dnssec-ksk-only) ($n)"
   ret=0
   $DIG $DIGOPTS $SECTIONS @10.53.0.2 $qtype $zone > dig.out.test$n
-  lines=$(awk -v qt="$qtype" '$4 == "RRSIG" && $5 == qt {print}' dig.out.test$n | wc -l)
-  grep $KSK_ID  dig.out.test$n > /dev/null && ret=1
-  grep $ZSK_ID  dig.out.test$n > /dev/null && ret=1
-  grep $ZSK_ID2 dig.out.test$n > /dev/null || ret=1
-  grep $ZSK_ID3 dig.out.test$n > /dev/null && ret=1
+  lines=$(get_keys_which_signed $qtype dig.out.test$n | wc -l)
   test "$lines" -eq 1 || ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$KSK_ID$" > /dev/null && ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$ZSK_ID2$" > /dev/null || ret=1
+  get_keys_which_signed $qtype dig.out.test$n | grep "^$ZSK_ID3$" > /dev/null && ret=1
   n=$((n+1))
   test "$ret" -eq 0 || echo_i "failed"
   status=$((status+ret))
@@ -3825,12 +3834,12 @@ status=$((status+ret))
 echo_i "checking DNSKEY RRset is signed with KSK only, new ZSK active (update-check-ksk, dnssec-ksk-only) ($n)"
 ret=0
 $DIG $DIGOPTS $SECTIONS @10.53.0.2 DNSKEY $zone > dig.out.test$n
-lines=$(awk '$4 == "RRSIG" && $5 == "DNSKEY" {print}' dig.out.test$n | wc -l)
+lines=$(get_keys_which_signed "DNSKEY" dig.out.test$n | wc -l)
 test "$lines" -eq 1 || ret=1
-grep $KSK_ID  dig.out.test$n > /dev/null || ret=1
-grep $ZSK_ID  dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID2 dig.out.test$n > /dev/null && ret=1
-grep $ZSK_ID3 dig.out.test$n > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$KSK_ID$" > /dev/null || ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID$" > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID2$" > /dev/null && ret=1
+get_keys_which_signed "DNSKEY" dig.out.test$n | grep "^$ZSK_ID3$" > /dev/null && ret=1
 n=$((n+1))
 test "$ret" -eq 0 || echo_i "failed"
 status=$((status+ret))

From 3c9a7ffac8d68b9662685b355611da3a1d204945 Mon Sep 17 00:00:00 2001
From: Matthijs Mekking <matthijs@isc.org>
Date: Wed, 24 Apr 2019 09:16:59 +0200
Subject: [PATCH 3/3] Wait for correct log message in dnssec/tests.sh

In 9.11 there are some log messages not existing, but the tests
rely on.  Adjust the grep call that gives confidence the rollover
step has occurred.
---
 bin/tests/system/dnssec/tests.sh | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/bin/tests/system/dnssec/tests.sh b/bin/tests/system/dnssec/tests.sh
index a93526d3d1..71bf407e16 100644
--- a/bin/tests/system/dnssec/tests.sh
+++ b/bin/tests/system/dnssec/tests.sh
@@ -3821,8 +3821,7 @@ done
 echo_i "wait until new ZSK $ZSK_ID3 active and ZSK $ZSK_ID2 inactive"
 for i in 1 2 3 4 5 6 7 8 9 10; do
     ret=0
-    grep "DNSKEY $zone/$DEFAULT_ALGORITHM/$ZSK_ID3 (ZSK) is now active" ns2/named.run > /dev/null || ret=1
-    grep "DNSKEY $zone/$DEFAULT_ALGORITHM/$ZSK_ID2 (ZSK) is now inactive" ns2/named.run > /dev/null || ret=1
+    grep "add re-sign updatecheck-kskonly\.secure\..*RRSIG.*SOA.*$ZSK_ID3.*$zone.*" ns2/named.run > /dev/null || ret=1
     [ "$ret" -eq 0 ] && break
     sleep 1
 done