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.

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

bin/tests/system/autosign/tests.sh

@@ -50,6 +50,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
+}
+
 freq() {
 	_file=$1
 	# remove first and last line that has incomplete set and skews the distribution
@@ -177,6 +183,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.
 #
@@ -1191,12 +1200,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:
@@ -1212,9 +1223,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: