From 6b4a17ef7c9aa48510f246d683b96f6838bd6d57 Mon Sep 17 00:00:00 2001 From: Matthijs Mekking Date: Fri, 6 Dec 2019 16:48:49 +0100 Subject: [PATCH 1/4] Save settime output --- bin/tests/system/autosign/clean.sh | 1 + bin/tests/system/autosign/tests.sh | 44 ++++++++++++++++-------------- 2 files changed, 24 insertions(+), 21 deletions(-) diff --git a/bin/tests/system/autosign/clean.sh b/bin/tests/system/autosign/clean.sh index afad4d3884..5148c7e176 100644 --- a/bin/tests/system/autosign/clean.sh +++ b/bin/tests/system/autosign/clean.sh @@ -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.* diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh index 84a2f902fb..392f2ffd11 100755 --- a/bin/tests/system/autosign/tests.sh +++ b/bin/tests/system/autosign/tests.sh @@ -207,7 +207,7 @@ 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 +$SETTIME -D now+5 ns3/Kinacksk3.example.+007+${id} > settime.out.test$n $RNDCCMD 10.53.0.3 loadkeys inacksk3.example 2>&1 | sed 's/^/ns3 /' | cat_i n=`expr $n + 1` @@ -235,7 +235,7 @@ 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 +$SETTIME -D now+5 ns3/Kinaczsk3.example.+007+${id} > settime.out.test$n $RNDCCMD 10.53.0.3 loadkeys inaczsk3.example 2>&1 | sed 's/^/ns3 /' | cat_i n=`expr $n + 1` if [ $ret != 0 ]; then echo_i "failed"; fi @@ -332,8 +332,8 @@ 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 +$SETTIME -K ns3 -P now -A now $zsk > settime.out.test$n.zsk +$SETTIME -K ns3 -P now -A now $ksk > settime.out.test$n.ksk $RNDCCMD 10.53.0.3 loadkeys autonsec3.example. 2>&1 | sed 's/^/ns3 /' | cat_i echo_i "waiting for changes to take effect" @@ -1006,9 +1006,9 @@ 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 file="ns3/`cat del2.key`.key" -$SETTIME -I now -D now $file > /dev/null +$SETTIME -I now -D now $file > settime.out.test$n.2 $RNDCCMD 10.53.0.3 sign secure-to-insecure2.example. 2>&1 | sed 's/^/ns3 /' | cat_i for i in 0 1 2 3 4 5 6 7 8 9; do ret=0 @@ -1087,8 +1087,8 @@ 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 +$SETTIME -K ns1 -i 0 -S $oldfile $newfile > settime.out.test$n.2 # note previous zone serial number oldserial=`$DIG $DIGOPTS +short soa . @10.53.0.1 | awk '{print $3}'` @@ -1097,7 +1097,7 @@ $RNDCCMD 10.53.0.1 loadkeys . 2>&1 | sed 's/^/ns1 /' | cat_i 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 $RNDCCMD 10.53.0.2 loadkeys bar. 2>&1 | sed 's/^/ns2 /' | cat_i @@ -1178,8 +1178,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,8 +1191,8 @@ 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 +$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" @@ -1207,8 +1209,8 @@ 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 +$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" @@ -1393,7 +1395,7 @@ 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 +$SETTIME -D sync now `cat sync.key` > settime.out.test$n $RNDCCMD 10.53.0.3 loadkeys sync.example | sed 's/^/ns3 /' | cat_i echo_i "checking that the CDS and CDNSKEY are deleted ($n)" @@ -1411,16 +1413,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=0 +grep "SYNC Delete:" settime.out.test$n >/dev/null || ret=0 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=0 +grep "SYNC Publish:" settime.out.test$n >/dev/null || ret=0 n=`expr $n + 1` if [ $ret != 0 ]; then echo_i "failed"; fi status=`expr $status + $ret` @@ -1527,7 +1529,7 @@ 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 for i in 0 1 2 3 4 5 6 7 8 9; do From cfaa631f65959d11a58ee6a9979c4bd289db4698 Mon Sep 17 00:00:00 2001 From: Matthijs Mekking Date: Fri, 6 Dec 2019 17:16:45 +0100 Subject: [PATCH 2/4] 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 .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 From 2e4273b55a27dcefa775161b1387fa25f95b678d Mon Sep 17 00:00:00 2001 From: Matthijs Mekking Date: Mon, 9 Dec 2019 08:26:46 +0100 Subject: [PATCH 3/4] 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 | 2 +- bin/tests/system/autosign/tests.sh | 19 +++++++++++++++---- 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/bin/tests/system/autosign/clean.sh b/bin/tests/system/autosign/clean.sh index 5148c7e176..8863fdbb26 100644 --- 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 diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh index 392f2ffd11..263e84beb5 100755 --- a/bin/tests/system/autosign/tests.sh +++ b/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: From bd4035900ad622c9201be6f323724760c68125cb Mon Sep 17 00:00:00 2001 From: Matthijs Mekking Date: Mon, 9 Dec 2019 11:22:57 +0100 Subject: [PATCH 4/4] Better error handling in autosign system test --- bin/tests/system/autosign/tests.sh | 100 ++++++++++++++--------------- 1 file changed, 50 insertions(+), 50 deletions(-) diff --git a/bin/tests/system/autosign/tests.sh b/bin/tests/system/autosign/tests.sh index 263e84beb5..014126e320 100755 --- a/bin/tests/system/autosign/tests.sh +++ b/bin/tests/system/autosign/tests.sh @@ -50,10 +50,11 @@ 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 +# 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() { @@ -216,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} > settime.out.test$n -$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 @@ -244,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} > settime.out.test$n -$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` @@ -341,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 > settime.out.test$n.zsk -$SETTIME -K ns3 -P now -A now $ksk > settime.out.test$n.ksk -$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 @@ -396,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() ( @@ -497,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` @@ -506,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` @@ -515,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` @@ -524,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` @@ -1015,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 > settime.out.test$n.1 +$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 > settime.out.test$n.2 -$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 @@ -1044,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 @@ -1065,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 ] @@ -1096,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 > settime.out.test$n.1 -$SETTIME -K ns1 -i 0 -S $oldfile $newfile > settime.out.test$n.2 +$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 > settime.out.test$n.3 +$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 @@ -1161,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 @@ -1200,14 +1201,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 +# 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 3 -wait_for_next_key_event "delay.example" "ns3" || ret=1 +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: @@ -1220,13 +1221,12 @@ status=`expr $status + $ret` echo_i "checking scheduled key activation ($n)" 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 +$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 3 -wait_for_next_key_event "delay.example" "ns3" || ret=1 - +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 @@ -1336,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` @@ -1346,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 @@ -1406,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` > settime.out.test$n -$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 @@ -1424,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.test$n || ret=0 -grep "SYNC Delete:" settime.out.test$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.test$n || ret=0 -grep "SYNC Publish:" settime.out.test$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` @@ -1542,7 +1542,7 @@ fi file="ns3/`cat delzsk.key`.key" $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