Move wait_for_log to conf.sh.common

diff --git a/bin/tests/system/conf.sh.common b/bin/tests/system/conf.sh.common
index e3975ce9a2a5871eea1e6f8df6b21cafc74ef21a..2b965deb8309c1cba154b439716b1b4a3250e53d 100644 (file)
--- 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 6d9ba5a646989144efd0891e39b4d4dbec0a58de..ccf2bf039bce8de0c409170fb18b4d5e86af2ec1 100644 (file)
--- 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 cb742264e5e3053eb5edaf03c4f1476d931898b1..7dbf0e8c574bbc67e2d7b91ecd7e2080e92c37eb 100644 (file)
--- 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 d39b076aaec3ae36d6a8f78a01c8f3de15e917c6..39d12a5697ffef04f4cde434f76b0b189f4d81b1 100644 (file)
--- 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 83191c2193e6a5192fa21ef22b2ed72901b1b852..9f57e30805c32af90bc466ca07ff9379195500d5 100644 (file)
--- 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