Fix race in autosign test

The autosign test has a test case where a DNSSEC maintaiend zone
has a set of DNSSEC keys without any timing metadata set.  It
tests if named picks up the key for publication and signing if a
delayed dnssec-settime/loadkeys event has occured.

The test failed intermittently despite the fact it sleeps for 5
seconds but the triggered key reconfigure action should happen after
3 seconds.

However, the test output showed that the test query came in before
the key reconfigure action was complete (see excerpts below).

The loadkeys command is received:

15:38:36 received control channel command 'loadkeys delay.example.'

The reconfiguring zone keys action is triggered after 3 seconds:

15:38:39 zone delay.example/IN: reconfiguring zone keys
15:38:39 DNSKEY delay.example/NSEC3RSASHA1/7484 (ZSK) is now published
15:38:39 DNSKEY delay.example/NSEC3RSASHA1/7455 (KSK) is now published
15:38:39 writing to journal

Two seconds later the test query comes in:

15:38:41 client @0x7f1b8c0562b0 10.53.0.1#44177: query
15:38:41 client @0x7f1b8c0562b0 10.53.0.1#44177: endrequest

And 6 more seconds later the reconfigure keys action is complete:

15:38:47 zone delay.example/IN: next key event: 05-Dec-2019 15:48:39

This commit fixes the test by checking the "next key event" log has
been seen before executing the test query, making sure that the
reconfigure keys action has been complete.

This commit however does not fix, nor explain why it took such a long
time (8 seconds) to reconfigure the keys.

(cherry picked from commit 2e4273b55a27dcefa775161b1387fa25f95b678d)

diff --git a/bin/tests/system/autosign/clean.sh b/bin/tests/system/autosign/clean.sh
index 5148c7e176b8634fabf434168007c36131126afd..8863fdbb265a3454e9a84bfa42a67500b8cd7532 100644 (file)
--- a/bin/tests/system/autosign/clean.sh
+++ b/bin/tests/system/autosign/clean.sh
@@ -14,7 +14,7 @@ rm -f */core
 rm -f */example.bk
 rm -f */named.conf
 rm -f */named.memstats
-rm -f */named.run
+rm -f */named.run*
 rm -f */trusted.conf */private.conf
 rm -f activate-now-publish-1day.key
 rm -f active.key inact.key del.key delzsk.key unpub.key standby.key rev.key

diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh
index bef0462d2f5d7b82a935900843f97f5d4ad25cfe..cabf435f0b990b83f0b8d470c0e50b061d934ee3 100755 (executable)
--- a/bin/tests/system/autosign/tests.sh
+++ b/bin/tests/system/autosign/tests.sh
@@ -61,6 +61,12 @@ checkprivate () {
     return 1
 }
 
+# wait until the next key event for zone $1 on server $2.
+wait_for_next_key_event () {
+       wait_for_log 10 "zone ${1}/IN: next key event:" "${2}/named.run" || return 1
+       return 0
+}
+
 # Check the signatures expiration times.  First check how many signatures
 # there are in total ($rrsigs).  Then see what the distribution of signature
 # expiration times is ($expiretimes).  Ignore the time part for a better
@@ -156,6 +162,9 @@ do
        $DIG $DIGOPTS $z @10.53.0.3 axfr | awk '$4 == "RRSIG" {print $9}' | sort | uniq -c | cat_i
 done
 
+# Set logfile offset for wait_for_log usage.
+nextpartreset ns3/named.run
+
 #
 # Check that DNSKEY is initially signed with a KSK and not a ZSK.
 #
@@ -1167,12 +1176,14 @@ status=`expr $status + $ret`
 
 echo_i "checking scheduled key publication, not activation ($n)"
 ret=0
+# Ensure initial reconfiguring zone keys event has passed.
+wait_for_next_key_event "delay.example" "ns3" || ret=1
 $SETTIME -K ns3 -P now+3s -A none $zsk > settime.out.test$n.zsk
 $SETTIME -K ns3 -P now+3s -A none $ksk > settime.out.test$n.ksk
 $RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i
-
 echo_i "waiting for changes to take effect"
-sleep 5
+sleep 3
+wait_for_next_key_event "delay.example" "ns3" || ret=1
 
 $DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 # DNSKEY expected:
@@ -1188,9 +1199,9 @@ ret=0
 $SETTIME -K ns3 -A now+3s $zsk > settime.out.test$n.zsk
 $SETTIME -K ns3 -A now+3s $ksk > settime.out.test$n.ksk
 $RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i
-
 echo_i "waiting for changes to take effect"
-sleep 5
+sleep 3
+wait_for_next_key_event "delay.example" "ns3" || ret=1
 
 $DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.1.test$n || ret=1
 # DNSKEY expected: