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)
(cherry picked from commit fb0ddd5bfe9fa504da0ca46573dfe0d85e56c7d9)

diff --git a/bin/tests/system/autosign/clean.sh b/bin/tests/system/autosign/clean.sh
index 533bcc2e914e9b8d2bba8408eab509b16bab98ab..371040f5c488703a3c3fb1f035cd3990ec62d55a 100644 (file)
--- a/bin/tests/system/autosign/clean.sh
+++ b/bin/tests/system/autosign/clean.sh
@@ -14,8 +14,8 @@ rm -f */core
 rm -f */example.bk
 rm -f */named.conf
 rm -f */named.memstats
-rm -f */named.run
-rm -f */named.conf
+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
 rm -f delayksk.key delayzsk.key autoksk.key autozsk.key

diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh
index 7e2b8efbe45dde5a05adf97196180ceb63acceff..03f458bba44d3436e12c7c23e1cf8055d22e25a4 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.
 #
@@ -1172,12 +1181,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:
@@ -1193,9 +1204,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: