From cfaa631f65959d11a58ee6a9979c4bd289db4698 Mon Sep 17 00:00:00 2001
From: Matthijs Mekking <matthijs@isc.org>
Date: Fri, 6 Dec 2019 17:16:45 +0100
Subject: [PATCH] Move wait_for_log to conf.sh.common

---
 bin/tests/system/conf.sh.common        | 39 ++++++++++++++++++++++++
 bin/tests/system/dnssec/tests.sh       | 16 ++--------
 bin/tests/system/mkeys/tests.sh        | 42 +++++++++-----------------
 bin/tests/system/statschannel/tests.sh | 16 ++--------
 bin/tests/system/tcp/tests.sh          | 13 +-------
 5 files changed, 58 insertions(+), 68 deletions(-)

diff --git a/bin/tests/system/conf.sh.common b/bin/tests/system/conf.sh.common
index e3975ce9a2..2b965deb83 100644
--- 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() {
diff --git a/bin/tests/system/dnssec/tests.sh b/bin/tests/system/dnssec/tests.sh
index 6d9ba5a646..ccf2bf039b 100644
--- 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
diff --git a/bin/tests/system/mkeys/tests.sh b/bin/tests/system/mkeys/tests.sh
index cb742264e5..7dbf0e8c57 100644
--- 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))
 
diff --git a/bin/tests/system/statschannel/tests.sh b/bin/tests/system/statschannel/tests.sh
index d39b076aae..39d12a5697 100644
--- 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
diff --git a/bin/tests/system/tcp/tests.sh b/bin/tests/system/tcp/tests.sh
index 83191c2193..9f57e30805 100644
--- 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