Merge branch '1457-intermittent-failure-autosign' into 'master'

Resolve "Intermittent failure in the autosign system test" Closes #1457 See merge request isc-projects/bind9!2729
2025-08-31 06:25:31 +00:00 · 2019-12-09 13:29:36 +00:00
parent edd6a084f0 bd4035900a
commit 910a7a56bc
7 changed files with 122 additions and 118 deletions
--- 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
@@ -63,6 +63,7 @@ rm -f ns3/secure.nsec3.example.db
 rm -f ns3/secure.optout.example.db
 rm -f ns3/sync.example.db
 rm -f ns3/ttl*.db
+rm -f ns3/settime.out.*
 rm -f nsupdate.out
 rm -f settime.out.*
 rm -f signing.out.*
--- a/bin/tests/system/autosign/tests.sh
+++ b/bin/tests/system/autosign/tests.sh
@@ -50,6 +50,13 @@ checkprivate () {
    return 1
 }

+# wait until notifies for zone $1 are sent by server $2. This is an indication
+# that the zone is signed with the active keys, and the changes have been
+# committed.
+wait_for_notifies () {
+	wait_for_log 10 "zone ${1}/IN: sending notifies" "${2}/named.run" || return 1
+}
+
 freq() {
 	_file=$1
 	# remove first and last line that has incomplete set and skews the distribution
@@ -177,6 +184,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.
 #
@@ -207,8 +217,8 @@ test $count -eq 3 || ret=1
 awk='$4 == "RRSIG" && $5 == "DNSKEY" { printf "%05u\n", $11 }'
 id=`awk "${awk}" dig.out.ns3.test$n`

-$SETTIME -D now+5 ns3/Kinacksk3.example.+007+${id} > /dev/null 2>&1
-$RNDCCMD 10.53.0.3 loadkeys inacksk3.example 2>&1 | sed 's/^/ns3 /' | cat_i
+$SETTIME -D now+5 ns3/Kinacksk3.example.+007+${id} > settime.out.test$n || ret=1
+($RNDCCMD 10.53.0.3 loadkeys inacksk3.example 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1

 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
@@ -235,8 +245,8 @@ count=`awk 'BEGIN { count = 0 }
       END {print count}' dig.out.ns3.test$n`
 test $count -eq 3 || ret=1
 id=`awk '$4 == "RRSIG" && $5 == "CNAME" { printf "%05u\n", $11 }' dig.out.ns3.test$n`
-$SETTIME -D now+5 ns3/Kinaczsk3.example.+007+${id} > /dev/null 2>&1
-$RNDCCMD 10.53.0.3 loadkeys inaczsk3.example 2>&1 | sed 's/^/ns3 /' | cat_i
+$SETTIME -D now+5 ns3/Kinaczsk3.example.+007+${id} > settime.out.test$n || ret=1
+($RNDCCMD 10.53.0.3 loadkeys inaczsk3.example 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -332,9 +342,9 @@ status=`expr $status + $ret`
 echo_i "signing preset nsec3 zone"
 zsk=`cat autozsk.key`
 ksk=`cat autoksk.key`
-$SETTIME -K ns3 -P now -A now $zsk > /dev/null 2>&1
-$SETTIME -K ns3 -P now -A now $ksk > /dev/null 2>&1
-$RNDCCMD 10.53.0.3 loadkeys autonsec3.example. 2>&1 | sed 's/^/ns3 /' | cat_i
+$SETTIME -K ns3 -P now -A now $zsk > settime.out.test$n.zsk || ret=1
+$SETTIME -K ns3 -P now -A now $ksk > settime.out.test$n.ksk || ret=1
+($RNDCCMD 10.53.0.3 loadkeys autonsec3.example. 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1

 echo_i "waiting for changes to take effect"
 sleep 3
@@ -387,9 +397,9 @@ status=`expr $status + $ret`
 # Send rndc sync command to ns1, ns2 and ns3, to force the dynamically
 # signed zones to be dumped to their zone files
 echo_i "dumping zone files"
-$RNDCCMD 10.53.0.1 sync 2>&1 | sed 's/^/ns1 /' | cat_i
-$RNDCCMD 10.53.0.2 sync 2>&1 | sed 's/^/ns2 /' | cat_i
-$RNDCCMD 10.53.0.3 sync 2>&1 | sed 's/^/ns3 /' | cat_i
+($RNDCCMD 10.53.0.1 sync 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
+($RNDCCMD 10.53.0.2 sync 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
+($RNDCCMD 10.53.0.3 sync 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1

 now="$(TZ=UTC date +%Y%m%d%H%M%S)"
 check_expiry() (
@@ -488,7 +498,7 @@ echo_i "checking TTLs of imported DNSKEYs (no default) ($n)"
 ret=0
 $DIG $DIGOPTS +tcp +noall +answer dnskey ttl1.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 [ -s dig.out.ns3.test$n ] || ret=1
-awk 'BEGIN {r=0} $2 != 300 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n || ret=1 | cat_i
+(awk 'BEGIN {r=0} $2 != 300 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n | cat_i) || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -497,7 +507,7 @@ echo_i "checking TTLs of imported DNSKEYs (with default) ($n)"
 ret=0
 $DIG $DIGOPTS +tcp +noall +answer dnskey ttl2.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 [ -s dig.out.ns3.test$n ] || ret=1
-awk 'BEGIN {r=0} $2 != 60 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n || ret=1 | cat_i
+(awk 'BEGIN {r=0} $2 != 60 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n | cat_i) || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -506,7 +516,7 @@ echo_i "checking TTLs of imported DNSKEYs (mismatched) ($n)"
 ret=0
 $DIG $DIGOPTS +tcp +noall +answer dnskey ttl3.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 [ -s dig.out.ns3.test$n ] || ret=1
-awk 'BEGIN {r=0} $2 != 30 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n || ret=1 | cat_i
+(awk 'BEGIN {r=0} $2 != 30 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n | cat_i) || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -515,7 +525,7 @@ echo_i "checking TTLs of imported DNSKEYs (existing RRset) ($n)"
 ret=0
 $DIG $DIGOPTS +tcp +noall +answer dnskey ttl4.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 [ -s dig.out.ns3.test$n ] || ret=1
-awk 'BEGIN {r=0} $2 != 30 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n || ret=1 | cat_i
+(awk 'BEGIN {r=0} $2 != 30 {r=1; print "found TTL " $2} END {exit r}' dig.out.ns3.test$n | cat_i) || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -1006,10 +1016,10 @@ status=`expr $status + $ret`
 echo_i "checking secure-to-insecure transition, scheduled ($n)"
 ret=0
 file="ns3/`cat del1.key`.key"
-$SETTIME -I now -D now $file > /dev/null
+$SETTIME -I now -D now $file > settime.out.test$n.1 || ret=1
 file="ns3/`cat del2.key`.key"
-$SETTIME -I now -D now $file > /dev/null
-$RNDCCMD 10.53.0.3 sign secure-to-insecure2.example. 2>&1 | sed 's/^/ns3 /' | cat_i
+$SETTIME -I now -D now $file > settime.out.test$n.2 || ret=1
+($RNDCCMD 10.53.0.3 sign secure-to-insecure2.example. 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 for i in 0 1 2 3 4 5 6 7 8 9; do
 	ret=0
 	$DIG $DIGOPTS axfr secure-to-insecure2.example @10.53.0.3 > dig.out.ns3.test$n || ret=1
@@ -1035,7 +1045,7 @@ END
 # Create DNSSEC keys in the zone directory.
 $KEYGEN -a rsasha1 -3 -q -K ns3 jitter.nsec3.example > /dev/null
 # Trigger zone signing.
-$RNDCCMD 10.53.0.3 sign jitter.nsec3.example. 2>&1 | sed 's/^/ns3 /' | cat_i
+($RNDCCMD 10.53.0.3 sign jitter.nsec3.example. 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 # Wait until zone has been signed.
 check_if_nsec3param_exists() {
 	$DIG $DIGOPTS NSEC3PARAM jitter.nsec3.example @10.53.0.3 > dig.out.ns3.1.test$n || return 1
@@ -1056,7 +1066,7 @@ oldinception=`$DIG $DIGOPTS +short soa prepub.example @10.53.0.3 | awk '/SOA/ {p

 $KEYGEN -a rsasha1 -3 -q -K ns3 -P 0 -A +6d -I +38d -D +45d prepub.example > /dev/null

-$RNDCCMD 10.53.0.3 sign prepub.example 2>&1 | sed 's/^/ns1 /' | cat_i
+($RNDCCMD 10.53.0.3 sign prepub.example 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
 newserial=$oldserial
 try=0
 while [ $oldserial -eq $newserial -a $try -lt 42 ]
@@ -1087,19 +1097,19 @@ oldfile=`cat active.key`
 oldid=$(keyfile_to_key_id "$(cat active.key)")
 newfile=`cat standby.key`
 newid=$(keyfile_to_key_id "$(cat standby.key)")
-$SETTIME -K ns1 -I now+2s -D now+25 $oldfile > /dev/null
-$SETTIME -K ns1 -i 0 -S $oldfile $newfile > /dev/null
+$SETTIME -K ns1 -I now+2s -D now+25 $oldfile > settime.out.test$n.1 || ret=1
+$SETTIME -K ns1 -i 0 -S $oldfile $newfile > settime.out.test$n.2 || ret=1

 # note previous zone serial number
 oldserial=`$DIG $DIGOPTS +short soa . @10.53.0.1 | awk '{print $3}'`

-$RNDCCMD 10.53.0.1 loadkeys . 2>&1 | sed 's/^/ns1 /' | cat_i
+($RNDCCMD 10.53.0.1 loadkeys . 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
 sleep 4

 echo_i "revoking key to duplicated key ID"
-$SETTIME -R now -K ns2 Kbar.+005+30676.key > /dev/null 2>&1
+$SETTIME -R now -K ns2 Kbar.+005+30676.key > settime.out.test$n.3 || ret=1

-$RNDCCMD 10.53.0.2 loadkeys bar. 2>&1 | sed 's/^/ns2 /' | cat_i
+($RNDCCMD 10.53.0.2 loadkeys bar. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1

 echo_i "waiting for changes to take effect"
 sleep 5
@@ -1152,7 +1162,7 @@ n=`expr $n + 1`
 status=`expr $status + $ret`

 echo_i "forcing full sign"
-$RNDCCMD 10.53.0.1 sign . 2>&1 | sed 's/^/ns1 /' | cat_i
+($RNDCCMD 10.53.0.1 sign . 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1

 echo_i "waiting for change to take effect"
 sleep 5
@@ -1178,8 +1188,10 @@ ret=0
 zsk=`cat delayzsk.key`
 ksk=`cat delayksk.key`
 # publication and activation times should be unset
-$SETTIME -K ns3 -pA -pP $zsk | grep -v UNSET > /dev/null 2>&1 && ret=1
-$SETTIME -K ns3 -pA -pP $ksk | grep -v UNSET > /dev/null 2>&1 && ret=1
+$SETTIME -K ns3 -pA -pP $zsk > settime.out.test$n.zsk || ret=1
+grep -v UNSET settime.out.test$n.zsk >/dev/null && ret=1
+$SETTIME -K ns3 -pA -pP $ksk > settime.out.test$n.ksk || ret=1
+grep -v UNSET settime.out.test$n.ksk >/dev/null && ret=1
 $DIG $DIGOPTS +noall +answer dnskey delay.example. @10.53.0.3 > dig.out.ns3.test$n || ret=1
 # DNSKEY not expected:
 awk 'BEGIN {r=1} $4=="DNSKEY" {r=0} END {exit r}' dig.out.ns3.test$n && ret=1
@@ -1189,12 +1201,14 @@ status=`expr $status + $ret`

 echo_i "checking scheduled key publication, not activation ($n)"
 ret=0
-$SETTIME -K ns3 -P now+3s -A none $zsk > /dev/null 2>&1
-$SETTIME -K ns3 -P now+3s -A none $ksk > /dev/null 2>&1
-$RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i
-
+# Ensure initial zone is loaded.
+wait_for_notifies "delay.example" "ns3" || ret=1
+$SETTIME -K ns3 -P now+3s -A none $zsk > settime.out.test$n.zsk || ret=1
+$SETTIME -K ns3 -P now+3s -A none $ksk > settime.out.test$n.ksk || ret=1
+($RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
 echo_i "waiting for changes to take effect"
-sleep 5
+sleep 3
+wait_for_notifies "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:
@@ -1207,13 +1221,12 @@ status=`expr $status + $ret`

 echo_i "checking scheduled key activation ($n)"
 ret=0
-$SETTIME -K ns3 -A now+3s $zsk > /dev/null 2>&1
-$SETTIME -K ns3 -A now+3s $ksk > /dev/null 2>&1
-$RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i
-
+$SETTIME -K ns3 -A now+3s $zsk > settime.out.test$n.zsk || ret=1
+$SETTIME -K ns3 -A now+3s $ksk > settime.out.test$n.ksk || ret=1
+($RNDCCMD 10.53.0.3 loadkeys delay.example. 2>&1 | sed 's/^/ns2 /' | cat_i) || ret=1
 echo_i "waiting for changes to take effect"
-sleep 5
-
+sleep 3
+wait_for_notifies "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:
 awk 'BEGIN {r=1} $4=="DNSKEY" {r=0} END {exit r}' dig.out.ns3.1.test$n || ret=1
@@ -1323,7 +1336,7 @@ status=`expr $status + $ret`
 echo_i "forcing full sign with unreadable keys ($n)"
 ret=0
 chmod 0 ns1/K.+*+*.key ns1/K.+*+*.private || ret=1
-$RNDCCMD 10.53.0.1 sign . 2>&1 | sed 's/^/ns1 /' | cat_i
+($RNDCCMD 10.53.0.1 sign . 2>&1 | sed 's/^/ns1 /' | cat_i) || ret=1
 $DIG $DIGOPTS . @10.53.0.1 dnskey > dig.out.ns1.test$n || ret=1
 grep "status: NOERROR" dig.out.ns1.test$n > /dev/null || ret=1
 n=`expr $n + 1`
@@ -1333,11 +1346,11 @@ status=`expr $status + $ret`
 echo_i "test turning on auto-dnssec during reconfig ($n)"
 ret=0
 # first create a zone that doesn't have auto-dnssec
-$RNDCCMD 10.53.0.3 addzone reconf.example '{ type master; file "reconf.example.db"; };' 2>&1 | sed 's/^/ns3 /' | cat_i
+($RNDCCMD 10.53.0.3 addzone reconf.example '{ type master; file "reconf.example.db"; };' 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 rekey_calls=`grep "zone reconf.example.*next key event" ns3/named.run | wc -l`
 [ "$rekey_calls" -eq 0 ] || ret=1
 # ...then we add auto-dnssec and reconfigure
-$RNDCCMD 10.53.0.3 modzone reconf.example '{ type master; file "reconf.example.db"; allow-update { any; }; auto-dnssec maintain; };' 2>&1 | sed 's/^/ns3 /' | cat_i
+($RNDCCMD 10.53.0.3 modzone reconf.example '{ type master; file "reconf.example.db"; allow-update { any; }; auto-dnssec maintain; };' 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 rndc_reconfig ns3 10.53.0.3
 for i in 0 1 2 3 4 5 6 7 8 9; do
    lret=0
@@ -1393,8 +1406,8 @@ if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`

 echo_i "setting CDS and CDNSKEY deletion times and calling 'rndc loadkeys'"
-$SETTIME -D sync now `cat sync.key` > /dev/null
-$RNDCCMD 10.53.0.3 loadkeys sync.example | sed 's/^/ns3 /' | cat_i
+$SETTIME -D sync now `cat sync.key` > settime.out.test$n || ret=1
+($RNDCCMD 10.53.0.3 loadkeys sync.example | sed 's/^/ns3 /' | cat_i) || ret=1

 echo_i "checking that the CDS and CDNSKEY are deleted ($n)"
 ret=0
@@ -1411,16 +1424,16 @@ status=`expr $status + $ret`

 echo_i "check that dnssec-settime -p Dsync works ($n)"
 ret=0
-$SETTIME -p Dsync `cat sync.key` > settime.out.$n|| ret=0
-grep "SYNC Delete:" settime.out.$n >/dev/null || ret=0
+$SETTIME -p Dsync `cat sync.key` > settime.out.test$n || ret=1
+grep "SYNC Delete:" settime.out.test$n >/dev/null || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`

 echo_i "check that dnssec-settime -p Psync works ($n)"
 ret=0
-$SETTIME -p Psync `cat sync.key` > settime.out.$n|| ret=0
-grep "SYNC Publish:" settime.out.$n >/dev/null || ret=0
+$SETTIME -p Psync `cat sync.key` > settime.out.test$n || ret=1
+grep "SYNC Publish:" settime.out.test$n >/dev/null || ret=1
 n=`expr $n + 1`
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=`expr $status + $ret`
@@ -1527,9 +1540,9 @@ if [ $_ret -ne 0 ]; then
 fi
 # Mark the inactive ZSK as pending removal.
 file="ns3/`cat delzsk.key`.key"
-$SETTIME -D now-1h $file > settime.out.test$n 2>&1 || ret=1
+$SETTIME -D now-1h $file > settime.out.test$n || ret=1
 # Trigger removal of the inactive ZSK and wait until its completion.
-$RNDCCMD 10.53.0.3 loadkeys delzsk.example 2>&1 | sed 's/^/ns3 /' | cat_i
+($RNDCCMD 10.53.0.3 loadkeys delzsk.example 2>&1 | sed 's/^/ns3 /' | cat_i) || ret=1
 for i in 0 1 2 3 4 5 6 7 8 9; do
 	_ret=1
 	$RNDCCMD 10.53.0.3 signing -list delzsk.example > signing.out.3.test$n 2>&1
--- a/bin/tests/system/conf.sh.common
+++ b/bin/tests/system/conf.sh.common
@@ -374,6 +374,45 @@ nextpartpeek() {
 	nextpartread $1 2> /dev/null
 }

+# _search_log: look for message $1 in file $2 with nextpart().
+_search_log() (
+	msg="$1"
+	file="$2"
+	nextpart "$file" | grep -F "$msg" > /dev/null
+)
+
+# _search_log_peek: look for message $1 in file $2 with nextpartpeek().
+_search_log_peek() (
+	msg="$1"
+	file="$2"
+	nextpartpeek "$file" | grep -F "$msg" > /dev/null
+)
+
+# wait_for_log: wait until message $2 in file $3 appears.  Bail out after
+# $1 seconds.  This needs to be used in conjunction with a prior call to
+# nextpart() or nextpartreset() on the same file to guarantee the offset is
+# set correctly.  Tests using wait_for_log() are responsible for cleaning up
+# the created <file>.prev files.
+wait_for_log() (
+	timeout="$1"
+	msg="$2"
+	file="$3"
+	retry_quiet "$timeout" _search_log "$msg" "$file" && return 0
+	echo_i "exceeded time limit waiting for '$msg' in $file"
+        return 1
+)
+
+# wait_for_log_peek: similar to wait_for_log() but peeking, so the file offset
+# does not change.
+wait_for_log_peek() (
+	timeout="$1"
+	msg="$2"
+	file="$3"
+	retry_quiet "$timeout" _search_log_peek "$msg" "$file" && return 0
+	echo_i "exceeded time limit waiting for '$msg' in $file"
+        return 1
+)
+
 # _retry: keep running a command until it succeeds, up to $1 times, with
 # one-second intervals, optionally printing a message upon every attempt
 _retry() {
--- a/bin/tests/system/dnssec/tests.sh
+++ b/bin/tests/system/dnssec/tests.sh
@@ -40,25 +40,13 @@ rndccmd() {
    "$RNDC" -c "$SYSTEMTESTTOP/common/rndc.conf" -p "$CONTROLPORT" -s "$@"
 }

-# TODO: Move wait_for_log and loadkeys_on to conf.sh.common
-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
-        done
-        echo_i "exceeded time limit waiting for '$msg' in $file"
-        ret=1
-}
-
+# TODO: Move loadkeys_on to conf.sh.common
 dnssec_loadkeys_on() {
 	nsidx=$1
 	zone=$2
 	nextpart ns${nsidx}/named.run > /dev/null
 	rndccmd 10.53.0.${nsidx} loadkeys ${zone} | sed "s/^/ns${nsidx} /" | cat_i
-	wait_for_log "next key event" ns${nsidx}/named.run
+	wait_for_log 20 "next key event" ns${nsidx}/named.run || return 1
 }

 # convert private-type records to readable form
--- a/bin/tests/system/mkeys/tests.sh
+++ b/bin/tests/system/mkeys/tests.sh
@@ -27,20 +27,6 @@ rndccmd() (
 	"$RNDC" -c "$SYSTEMTESTTOP/common/rndc.conf" -p "${CONTROLPORT}" -s "$@"
 )

-search_log() (
-	msg=$1
-	file=$2
-	nextpart "$file" | grep -F "$msg" > /dev/null
-)
-
-wait_for_log() (
-	msg="$1"
-	file="$2"
-	retry_quiet 20 search_log "$msg" "$file" && return 0
-	echo_i "exceeded time limit waiting for '$msg' in $file"
-	return 1
-)
-
 mkeys_reconfig_on() (
 	nsidx=$1
 	rndccmd "10.53.0.${nsidx}" reconfig . | sed "s/^/ns${nsidx} /" | cat_i
@@ -50,21 +36,21 @@ mkeys_reload_on() (
 	nsidx=$1
 	nextpart "ns${nsidx}"/named.run > /dev/null
 	rndc_reload "ns${nsidx}" "10.53.0.${nsidx}"
-	wait_for_log "loaded serial" "ns${nsidx}"/named.run
+	wait_for_log 20 "loaded serial" "ns${nsidx}"/named.run || return 1
 )

 mkeys_loadkeys_on() (
 	nsidx=$1
 	nextpart "ns${nsidx}"/named.run > /dev/null
 	rndccmd "10.53.0.${nsidx}" loadkeys . | sed "s/^/ns${nsidx} /" | cat_i
-	wait_for_log "next key event" "ns${nsidx}"/named.run
+	wait_for_log 20 "next key event" "ns${nsidx}"/named.run || return 1
 )

 mkeys_refresh_on() (
 	nsidx=$1
 	nextpart "ns${nsidx}"/named.run > /dev/null
 	rndccmd "10.53.0.${nsidx}" managed-keys refresh | sed "s/^/ns${nsidx} /" | cat_i
-	wait_for_log "Returned from key fetch in keyfetch_done()" "ns${nsidx}"/named.run
+	wait_for_log 20 "Returned from key fetch in keyfetch_done()" "ns${nsidx}"/named.run || return 1
 )

 mkeys_sync_on() (
@@ -75,7 +61,7 @@ mkeys_sync_on() (
 	nsidx=$1
 	nextpart "ns${nsidx}"/named.run > /dev/null
 	rndccmd "10.53.0.${nsidx}" managed-keys sync | sed "s/^/ns${nsidx} /" | cat_i
-	wait_for_log "dump_done" "ns${nsidx}"/named.run
+	wait_for_log 20 "dump_done" "ns${nsidx}"/named.run || return 1
 )

 mkeys_status_on() (
@@ -322,7 +308,7 @@ $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns2
 n=$((n+1))
 echo_i "check that no key from bind.keys is marked as an initializing key ($n)"
 ret=0
-wait_for_log "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
 mkeys_secroots_on 2 || ret=1
 grep '; initializing' ns2/named.secroots > /dev/null 2>&1 && ret=1
 if [ $ret != 0 ]; then echo_i "failed"; fi
@@ -338,7 +324,7 @@ $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns2
 n=$((n+1))
 echo_i "check that standby key is now trusted ($n)"
 ret=0
-wait_for_log "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
 mkeys_status_on 2 > rndc.out.$n 2>&1 || ret=1
 # two keys listed
 count=$(grep -c "keyid: " rndc.out.$n) || true
@@ -495,7 +481,7 @@ $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns2
 n=$((n+1))
 echo_i "check positive validation ($n)"
 ret=0
-wait_for_log "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done()" ns2/named.run || ret=1
 dig_with_opts +noauth example. @10.53.0.2 txt > dig.out.ns2.test$n || ret=1
 grep "flags:.*ad.*QUERY" dig.out.ns2.test$n > /dev/null || ret=1
 grep "example..*.RRSIG..*TXT" dig.out.ns2.test$n > /dev/null || ret=1
@@ -591,7 +577,7 @@ rm -f ns1/root.db.signed.jnl
 cp ns1/root.db ns1/root.db.signed
 nextpart ns1/named.run > /dev/null
 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns1
-wait_for_log "all zones loaded" ns1/named.run || ret=1
+wait_for_log 20 "all zones loaded" ns1/named.run || ret=1
 mkeys_refresh_on 2 || ret=1
 mkeys_status_on 2 > rndc.out.2.$n 2>&1 || ret=1
 # one key listed
@@ -625,7 +611,7 @@ rm -f ns1/root.db.signed.jnl
 cat ns1/K*.key >> ns1/root.db.signed
 nextpart ns1/named.run > /dev/null
 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns1
-wait_for_log "all zones loaded" ns1/named.run || ret=1
+wait_for_log 20 "all zones loaded" ns1/named.run || ret=1
 # Less than a second may have passed since the last time ns2 received a
 # ./DNSKEY response from ns1.  Ensure keys are refreshed at a different
 # timestamp to prevent minimal update from resetting it to the same timestamp.
@@ -725,7 +711,7 @@ ret=0
 $PERL $SYSTEMTESTTOP/stop.pl --use-rndc --port "${CONTROLPORT}" mkeys ns5
 nextpart ns5/named.run > /dev/null
 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns5
-wait_for_log "Returned from key fetch in keyfetch_done()" ns5/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done()" ns5/named.run || ret=1
 # ns5/named.run will contain logs from both the old instance and the new
 # instance.  In order for the test to pass, both must attempt a fetch.
 count=$(grep -c "Creating key fetch" ns5/named.run) || true
@@ -744,7 +730,7 @@ rm -f ns5/managed-keys.bind*
 cp ns5/named2.args ns5/named.args
 nextpart ns5/named.run > /dev/null
 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns5
-wait_for_log "Returned from key fetch in keyfetch_done() for '.': failure" ns5/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done() for '.': failure" ns5/named.run || ret=1
 mkeys_secroots_on 5 || ret=1
 grep '; initializing managed' ns5/named.secroots > /dev/null 2>&1 || ret=1
 # ns1 should still REFUSE queries from ns5, so resolving should be impossible
@@ -757,7 +743,7 @@ copy_setports ns1/named3.conf.in ns1/named.conf
 rm -f ns1/root.db.signed.jnl
 nextpart ns5/named.run > /dev/null
 mkeys_reconfig_on 1 || ret=1
-wait_for_log "Returned from key fetch in keyfetch_done() for '.': success" ns5/named.run || ret=1
+wait_for_log 20 "Returned from key fetch in keyfetch_done() for '.': success" ns5/named.run || ret=1
 mkeys_secroots_on 5 || ret=1
 grep '; managed' ns5/named.secroots > /dev/null || ret=1
 # ns1 should not longer REFUSE queries from ns5, so managed keys should be
@@ -777,7 +763,7 @@ rm -f ns6/managed-keys.bind*
 nextpart ns6/named.run > /dev/null
 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port "${PORT}" mkeys ns6
 # log when an unsupported algorithm is encountered during startup
-wait_for_log "ignoring initial-key for 'unsupported.': algorithm is unsupported" ns6/named.run || ret=1
+wait_for_log 20 "ignoring initial-key for 'unsupported.': algorithm is unsupported" ns6/named.run || ret=1
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=$((status+ret))

@@ -819,7 +805,7 @@ count=$(grep -c "keyid: " rndc.out.$n) || true
 count=$(grep -c "trust" rndc.out.$n) || true
 [ "$count" -eq 2 ] || ret=1
 # log when an unsupported algorithm is encountered during rollover
-wait_for_log "Cannot compute tag for key in zone .: algorithm is unsupported" ns6/named.run || ret=1
+wait_for_log 20 "Cannot compute tag for key in zone .: algorithm is unsupported" ns6/named.run || ret=1
 if [ $ret != 0 ]; then echo_i "failed"; fi
 status=$((status+ret))

--- a/bin/tests/system/statschannel/tests.sh
+++ b/bin/tests/system/statschannel/tests.sh
@@ -76,25 +76,13 @@ getzones() {
    return $result
 }

-# TODO: Move wait_for_log and loadkeys_on to conf.sh.common
-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
-    done
-    echo_i "exceeded time limit waiting for '$msg' in $file"
-    ret=1
-}
-
+# TODO: Move loadkeys_on to conf.sh.common
 loadkeys_on() {
    nsidx=$1
    zone=$2
    nextpart ns${nsidx}/named.run > /dev/null
    $RNDCCMD 10.53.0.${nsidx} loadkeys ${zone} | sed "s/^/ns${nsidx} /" | cat_i
-    wait_for_log "next key event" ns${nsidx}/named.run
+    wait_for_log 20 "next key event" ns${nsidx}/named.run
 }

 status=0
--- a/bin/tests/system/tcp/tests.sh
+++ b/bin/tests/system/tcp/tests.sh
@@ -78,22 +78,11 @@ refresh_tcp_stats() {
 	TCP_HIGH="$(sed -n "s/^TCP high-water: \([0-9][0-9]*\)/\1/p" rndc.out.$n)"
 }

-wait_for_log() {
-	msg=$1
-	file=$2
-	for _ in 1 2 3 4 5 6 7 8 9 10; do
-		nextpartpeek "$file" | grep "$msg" > /dev/null && return
-		sleep 1
-	done
-	echo_i "exceeded time limit waiting for '$msg' in $file"
-	ret=1
-}
-
 # Send a command to the tool script listening on 10.53.0.6.
 send_command() {
 	nextpart ans6/ans.run > /dev/null
 	echo "$*" | "${PERL}" "${SYSTEMTESTTOP}/send.pl" 10.53.0.6 "${CONTROLPORT}"
-	wait_for_log "result=" ans6/ans.run
+	wait_for_log_peek 10 "result=" ans6/ans.run || ret=1
 	if ! nextpartpeek ans6/ans.run | grep -qF "result=OK"; then
 		return 1
 	fi