From 05aa45c602f564dfe089b091686313f69697fa81 Mon Sep 17 00:00:00 2001 From: Mark Andrews Date: Tue, 10 Dec 2019 14:53:00 +1100 Subject: [PATCH] improve forensic logs improve forensic logs by directing output to per sub-test named files and reporting the sub-subtest number. --- bin/tests/system/xfer/tests.sh | 245 +++++++++++++++++---------------- 1 file changed, 124 insertions(+), 121 deletions(-) diff --git a/bin/tests/system/xfer/tests.sh b/bin/tests/system/xfer/tests.sh index 53501a2f49..b26543e9a1 100755 --- a/bin/tests/system/xfer/tests.sh +++ b/bin/tests/system/xfer/tests.sh @@ -18,40 +18,41 @@ RNDCCMD="$RNDC -c $SYSTEMTESTTOP/common/rndc.conf -p ${CONTROLPORT} -s" status=0 n=0 -n=`expr $n + 1` -echo_i "testing basic zone transfer functionality (from primary)" +n=$((n+1)) +echo_i "testing basic zone transfer functionality (from primary) ($n)" tmp=0 $DIG $DIGOPTS example. \ - @10.53.0.2 axfr > dig.out.ns2 || tmp=1 -grep "^;" dig.out.ns2 | cat_i + @10.53.0.2 axfr > dig.out.ns2.test$n || tmp=1 +grep "^;" dig.out.ns2.test$n | cat_i + +digcomp dig1.good dig.out.ns2.test$n || tmp=1 -digcomp dig1.good dig.out.ns2 || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` +n=$((n+1)) echo_i "testing basic zone transfer functionality (from secondary) ($n)" # # Spin to allow the zone to tranfer. # for i in 1 2 3 4 5 do -tmp=0 -$DIG $DIGOPTS example. \ - @10.53.0.3 axfr > dig.out.ns3 || tmp=1 - grep "^;" dig.out.ns3 > /dev/null || break - echo_i "plain zone re-transfer" - sleep 5 + tmp=0 + $DIG $DIGOPTS example. \ + @10.53.0.3 axfr > dig.out.ns3.test$n || tmp=1 + grep "^;" dig.out.ns3.test$n > /dev/null || break + echo_i "plain zone re-transfer" + sleep 5 done -grep "^;" dig.out.ns3 | cat_i -digcomp dig1.good dig.out.ns3 || tmp=1 +grep "^;" dig.out.ns3.test$n | cat_i +digcomp dig1.good dig.out.ns3.test$n || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing TSIG signed zone transfers" -$DIG $DIGOPTS tsigzone. @10.53.0.2 axfr -y tsigzone.:1234abcd8765 > dig.out.ns2 || status=1 -grep "^;" dig.out.ns2 | cat_i +n=$((n+1)) +echo_i "testing TSIG signed zone transfers ($n)" +$DIG $DIGOPTS tsigzone. @10.53.0.2 axfr -y tsigzone.:1234abcd8765 > dig.out.ns2.test$n || status=1 +grep "^;" dig.out.ns2.test$n | cat_i # # Spin to allow the zone to tranfer. @@ -59,16 +60,16 @@ grep "^;" dig.out.ns2 | cat_i for i in 1 2 3 4 5 do tmp=0 - $DIG $DIGOPTS tsigzone. @10.53.0.3 axfr -y tsigzone.:1234abcd8765 > dig.out.ns3 || tmp=1 - grep "^;" dig.out.ns3 > /dev/null + $DIG $DIGOPTS tsigzone. @10.53.0.3 axfr -y tsigzone.:1234abcd8765 > dig.out.ns3.test$n || tmp=1 + grep "^;" dig.out.ns3.test$n > /dev/null if test $? -ne 0 ; then break; fi echo_i "plain zone re-transfer" sleep 5 done if test $tmp -eq 1 ; then status=1; fi -grep "^;" dig.out.ns3 | cat_i +grep "^;" dig.out.ns3.test$n | cat_i -digcomp dig.out.ns2 dig.out.ns3 || status=1 +digcomp dig.out.ns2.test$n dig.out.ns3.test$n || status=1 echo_i "reload servers for in preparation for ixfr-from-differences tests" @@ -112,28 +113,29 @@ rndc_reload ns7 10.53.0.7 sleep 3 -echo_i "testing zone is dumped after successful transfer" +n=$((n+1)) +echo_i "testing zone is dumped after successful transfer ($n)" $DIG $DIGOPTS +noall +answer +multi @10.53.0.2 \ - slave. soa > dig.out.ns2 || tmp=1 -grep "1397051952 ; serial" dig.out.ns2 > /dev/null 2>&1 || tmp=1 + slave. soa > dig.out.ns2.test$n || tmp=1 +grep "1397051952 ; serial" dig.out.ns2.test$n > /dev/null 2>&1 || tmp=1 grep "1397051952 ; serial" ns2/slave.db > /dev/null 2>&1 || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing ixfr-from-differences yes;" +n=$((n+1)) +echo_i "testing ixfr-from-differences yes; ($n)" tmp=0 for i in 0 1 2 3 4 5 6 7 8 9 do a=0 b=0 c=0 d=0 echo_i "wait for reloads..." - $DIG $DIGOPTS @10.53.0.6 +noall +answer soa master > dig.out.soa1.ns6 - grep "1397051953" dig.out.soa1.ns6 > /dev/null && a=1 - $DIG $DIGOPTS @10.53.0.1 +noall +answer soa slave > dig.out.soa2.ns1 - grep "1397051953" dig.out.soa2.ns1 > /dev/null && b=1 - $DIG $DIGOPTS @10.53.0.2 +noall +answer soa example > dig.out.soa3.ns2 - grep "1397051953" dig.out.soa3.ns2 > /dev/null && c=1 + $DIG $DIGOPTS @10.53.0.6 +noall +answer soa master > dig.out.soa1.ns6.test$n + grep "1397051953" dig.out.soa1.ns6.test$n > /dev/null && a=1 + $DIG $DIGOPTS @10.53.0.1 +noall +answer soa slave > dig.out.soa2.ns1.test$n + grep "1397051953" dig.out.soa2.ns1.test$n > /dev/null && b=1 + $DIG $DIGOPTS @10.53.0.2 +noall +answer soa example > dig.out.soa3.ns2.test$n + grep "1397051953" dig.out.soa3.ns2.test$n > /dev/null && c=1 [ $a -eq 1 -a $b -eq 1 -a $c -eq 1 ] && break sleep 2 done @@ -142,12 +144,12 @@ for i in 0 1 2 3 4 5 6 7 8 9 do a=0 b=0 c=0 d=0 echo_i "wait for transfers..." - $DIG $DIGOPTS @10.53.0.3 +noall +answer soa example > dig.out.soa1.ns3 - grep "1397051953" dig.out.soa1.ns3 > /dev/null && a=1 - $DIG $DIGOPTS @10.53.0.3 +noall +answer soa master > dig.out.soa2.ns3 - grep "1397051953" dig.out.soa2.ns3 > /dev/null && b=1 - $DIG $DIGOPTS @10.53.0.6 +noall +answer soa slave > dig.out.soa3.ns6 - grep "1397051953" dig.out.soa3.ns6 > /dev/null && c=1 + $DIG $DIGOPTS @10.53.0.3 +noall +answer soa example > dig.out.soa1.ns3.test$n + grep "1397051953" dig.out.soa1.ns3.test$n > /dev/null && a=1 + $DIG $DIGOPTS @10.53.0.3 +noall +answer soa master > dig.out.soa2.ns3.test$n + grep "1397051953" dig.out.soa2.ns3.test$n > /dev/null && b=1 + $DIG $DIGOPTS @10.53.0.6 +noall +answer soa slave > dig.out.soa3.ns6.test$n + grep "1397051953" dig.out.soa3.ns6.test$n > /dev/null && c=1 [ $a -eq 1 -a $b -eq 1 -a $c -eq 1 ] && break # re-notify if necessary @@ -158,62 +160,62 @@ do done $DIG $DIGOPTS example. \ - @10.53.0.3 axfr > dig.out.ns3 || tmp=1 -grep "^;" dig.out.ns3 | cat_i + @10.53.0.3 axfr > dig.out.ns3.test$n || tmp=1 +grep "^;" dig.out.ns3.test$n | cat_i -digcomp dig2.good dig.out.ns3 || tmp=1 +digcomp dig2.good dig.out.ns3.test$n || tmp=1 # ns3 has a journal iff it received an IXFR. test -f ns3/example.bk || tmp=1 test -f ns3/example.bk.jnl || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing ixfr-from-differences master; (master zone)" +n=$((n+1)) +echo_i "testing ixfr-from-differences master; (master zone) ($n)" tmp=0 $DIG $DIGOPTS master. \ - @10.53.0.6 axfr > dig.out.ns6 || tmp=1 -grep "^;" dig.out.ns6 | cat_i + @10.53.0.6 axfr > dig.out.ns6.test$n || tmp=1 +grep "^;" dig.out.ns6.test$n | cat_i $DIG $DIGOPTS master. \ - @10.53.0.3 axfr > dig.out.ns3 || tmp=1 -grep "^;" dig.out.ns3 > /dev/null && cat_i dig.out.ns3 + @10.53.0.3 axfr > dig.out.ns3.test$n || tmp=1 +grep "^;" dig.out.ns3.test$n > /dev/null && cat_i dig.out.ns3.test$n -digcomp dig.out.ns6 dig.out.ns3 || tmp=1 +digcomp dig.out.ns6.test$n dig.out.ns3.test$n || tmp=1 # ns3 has a journal iff it received an IXFR. test -f ns3/master.bk || tmp=1 test -f ns3/master.bk.jnl || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing ixfr-from-differences master; (slave zone)" +n=$((n+1)) +echo_i "testing ixfr-from-differences master; (slave zone) ($n)" tmp=0 $DIG $DIGOPTS slave. \ - @10.53.0.6 axfr > dig.out.ns6 || tmp=1 -grep "^;" dig.out.ns6 | cat_i + @10.53.0.6 axfr > dig.out.ns6.test$n || tmp=1 +grep "^;" dig.out.ns6.test$n | cat_i $DIG $DIGOPTS slave. \ - @10.53.0.1 axfr > dig.out.ns1 || tmp=1 -grep "^;" dig.out.ns1 | cat_i + @10.53.0.1 axfr > dig.out.ns1.test$n || tmp=1 +grep "^;" dig.out.ns1.test$n | cat_i -digcomp dig.out.ns6 dig.out.ns1 || tmp=1 +digcomp dig.out.ns6.test$n dig.out.ns1.test$n || tmp=1 # ns6 has a journal iff it received an IXFR. test -f ns6/slave.bk || tmp=1 test -f ns6/slave.bk.jnl && tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing ixfr-from-differences slave; (master zone)" +n=$((n+1)) +echo_i "testing ixfr-from-differences slave; (master zone) ($n)" tmp=0 # ns7 has a journal iff it generates an IXFR. @@ -221,35 +223,36 @@ test -f ns7/master2.db || tmp=1 test -f ns7/master2.db.jnl && tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "testing ixfr-from-differences slave; (slave zone)" +n=$((n+1)) +echo_i "testing ixfr-from-differences slave; (slave zone) ($n)" tmp=0 $DIG $DIGOPTS slave. \ - @10.53.0.1 axfr > dig.out.ns1 || tmp=1 -grep "^;" dig.out.ns1 | cat_i + @10.53.0.1 axfr > dig.out.ns1.test$n || tmp=1 +grep "^;" dig.out.ns1.test$n | cat_i $DIG $DIGOPTS slave. \ - @10.53.0.7 axfr > dig.out.ns7 || tmp=1 -grep "^;" dig.out.ns1 | cat_i + @10.53.0.7 axfr > dig.out.ns7.test$n || tmp=1 +grep "^;" dig.out.ns7.test$n | cat_i -digcomp dig.out.ns7 dig.out.ns1 || tmp=1 +digcomp dig.out.ns7.test$n dig.out.ns1.test$n || tmp=1 # ns7 has a journal iff it generates an IXFR. test -f ns7/slave.bk || tmp=1 test -f ns7/slave.bk.jnl || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -echo_i "check that a multi-message uncompressable zone transfers" +n=$((n+1)) +echo_i "check that a multi-message uncompressable zone transfers ($n)" $DIG axfr . -p ${PORT} @10.53.0.4 | grep SOA > axfr.out if test `wc -l < axfr.out` != 2 then echo_i "failed" - status=`expr $status + 1` + status=$((status+1)) fi # now we test transfers with assorted TSIG glitches @@ -280,20 +283,20 @@ rndc_reload ns4 10.53.0.4 for i in 0 1 2 3 4 5 6 7 8 9 do - $DIGCMD nil. SOA > dig.out.ns4 - grep SOA dig.out.ns4 > /dev/null && break + $DIGCMD nil. SOA > dig.out.ns4.test$n + grep SOA dig.out.ns4.test$n > /dev/null && break sleep 1 done sed -n "$cur,\$p" < ns4/named.run | grep "Transfer status: success" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'initial AXFR' >/dev/null || { echo_i "failed" - status=1 + status=$((status+1)) } echo_i "unsigned transfer" @@ -307,13 +310,13 @@ sleep 2 sed -n "$cur,\$p" < ns4/named.run | grep "Transfer status: expected a TSIG or SIG(0)" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'unsigned AXFR' >/dev/null && { echo_i "failed" - status=1 + status=$((status+1)) } echo_i "bad keydata" @@ -327,13 +330,13 @@ sleep 2 sed -n "$cur,\$p" < ns4/named.run | grep "Transfer status: tsig verify failure" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'bad keydata AXFR' >/dev/null && { echo_i "failed" - status=1 + status=$((status+1)) } echo_i "partially-signed transfer" @@ -347,13 +350,13 @@ sleep 2 sed -n "$cur,\$p" < ns4/named.run | grep "Transfer status: expected a TSIG or SIG(0)" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'partially signed AXFR' >/dev/null && { echo_i "failed" - status=1 + status=$((status+1)) } echo_i "unknown key" @@ -367,13 +370,13 @@ sleep 2 sed -n "$cur,\$p" < ns4/named.run | grep "tsig key 'tsig_key': key name and algorithm do not match" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'unknown key AXFR' >/dev/null && { echo_i "failed" - status=1 + status=$((status+1)) } echo_i "incorrect key" @@ -387,16 +390,16 @@ sleep 2 sed -n "$cur,\$p" < ns4/named.run | grep "tsig key 'tsig_key': key name and algorithm do not match" > /dev/null || { echo_i "failed: expected status was not logged" - status=1 + status=$((status+1)) } cur=`awk 'END {print NR}' ns4/named.run` $DIGCMD nil. TXT | grep 'incorrect key AXFR' >/dev/null && { echo_i "failed" - status=1 + status=$((status+1)) } -n=`expr $n + 1` +n=$((n+1)) echo_i "check that we ask for and get a EDNS EXPIRE response ($n)" # force a refresh query $RNDCCMD 10.53.0.7 refresh edns-expire 2>&1 | sed 's/^/ns7 /' | cat_i @@ -406,59 +409,59 @@ sleep 10 expire=`awk '/edns-expire\/IN: got EDNS EXPIRE of/ { x=$9 } END { print x }' ns7/named.run` test ${expire:-0} -gt 0 -a ${expire:-0} -lt 1814400 || { echo_i "failed (expire=${expire:-0})" - status=1 + status=$((status+1)) } -n=`expr $n + 1` +n=$((n+1)) echo_i "test smaller transfer TCP message size ($n)" $DIG $DIGOPTS example. @10.53.0.8 axfr \ - -y key1.:1234abcd8765 > dig.out.msgsize || status=1 + -y key1.:1234abcd8765 > dig.out.msgsize.test$n || status=1 -$DOS2UNIX dig.out.msgsize >/dev/null 2>&1 +$DOS2UNIX dig.out.msgsize.test$n >/dev/null 2>&1 -bytes=`wc -c < dig.out.msgsize` +bytes=`wc -c < dig.out.msgsize.test$n` if [ $bytes -ne 459357 ]; then echo_i "failed axfr size check" - status=1 + status=$((status+1)) fi num_messages=`cat ns8/named.run | grep "sending TCP message of" | wc -l` if [ $num_messages -le 300 ]; then echo_i "failed transfer message count check" - status=1 + status=$((status+1)) fi -n=`expr $n + 1` +n=$((n+1)) echo_i "test mapped zone with out of zone data ($n)" tmp=0 -$DIG -p ${PORT} txt mapped @10.53.0.3 > dig.out.1 -grep "status: NOERROR," dig.out.1 > /dev/null || tmp=1 +$DIG -p ${PORT} txt mapped @10.53.0.3 > dig.out.1.test$n +grep "status: NOERROR," dig.out.1.test$n > /dev/null || tmp=1 $PERL $SYSTEMTESTTOP/stop.pl xfer ns3 $PERL $SYSTEMTESTTOP/start.pl --noclean --restart --port ${PORT} xfer ns3 for try in 0 1 2 3 4 5 6 7 8 9; do iret=0 - $DIG -p ${PORT} txt mapped @10.53.0.3 > dig.out.2 - grep "status: NOERROR," dig.out.2 > /dev/null || iret=1 + $DIG -p ${PORT} txt mapped @10.53.0.3 > dig.out.2.test$n + grep "status: NOERROR," dig.out.2.test$n > /dev/null || iret=1 if [ "$iret" -eq 0 ] then - $DIG -p ${PORT} axfr mapped @10.53.0.3 > dig.out.3 - digcomp knowngood.mapped dig.out.3 || iret=1 + $DIG -p ${PORT} axfr mapped @10.53.0.3 > dig.out.3.test$n + digcomp knowngood.mapped dig.out.3.test$n || iret=1 fi [ "$iret" -eq 0 ] && break sleep 1 done [ "$iret" -eq 0 ] || tmp=1 [ "$tmp" -ne 0 ] && echo_i "failed" -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` +n=$((n+1)) echo_i "test that a zone with too many records is rejected (AXFR) ($n)" tmp=0 grep "'axfr-too-big/IN'.*: too many records" ns6/named.run >/dev/null || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` +n=$((n+1)) echo_i "test that a zone with too many records is rejected (IXFR) ($n)" tmp=0 grep "'ixfr-too-big./IN.*: too many records" ns6/named.run >/dev/null && tmp=1 @@ -475,18 +478,18 @@ do done grep "'ixfr-too-big/IN'.*: too many records" ns6/named.run >/dev/null || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "checking whether dig calculates AXFR statistics correctly" +n=$((n+1)) +echo_i "checking whether dig calculates AXFR statistics correctly ($n)" # Loop until the secondary server manages to transfer the "xfer-stats" zone so # that we can both check dig output and immediately proceed with the next test. # Use -b so that we can discern between incoming and outgoing transfers in ns3 # logs later on. tmp=1 for i in 1 2 3 4 5 6 7 8 9 10; do - $DIG $DIGOPTS +noedns +stat -b 10.53.0.2 @10.53.0.3 xfer-stats. AXFR > dig.out.ns3.$n - if grep "; Transfer failed" dig.out.ns3.$n > /dev/null; then + $DIG $DIGOPTS +noedns +stat -b 10.53.0.2 @10.53.0.3 xfer-stats. AXFR > dig.out.ns3.test$n + if grep "; Transfer failed" dig.out.ns3.test$n > /dev/null; then sleep 1 else tmp=0 @@ -496,25 +499,25 @@ done if [ $tmp -ne 0 ]; then echo_i "timed out waiting for zone transfer" else - get_dig_xfer_stats dig.out.ns3.$n > stats.dig + get_dig_xfer_stats dig.out.ns3.test$n > stats.dig diff axfr-stats.good stats.dig || tmp=1 fi if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) # Note: in the next two tests, we use ns3 logs for checking both incoming and # outgoing transfer statistics as ns3 is both a secondary server (for ns1) and a # primary server (for dig queries from the previous test) for "xfer-stats". -n=`expr $n + 1` -echo_i "checking whether named calculates incoming AXFR statistics correctly" +n=$((n+1)) +echo_i "checking whether named calculates incoming AXFR statistics correctly ($n)" tmp=0 get_named_xfer_stats ns3/named.run 10.53.0.1 xfer-stats "Transfer completed" > stats.incoming diff axfr-stats.good stats.incoming || tmp=1 if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) -n=`expr $n + 1` -echo_i "checking whether named calculates outgoing AXFR statistics correctly" +n=$((n+1)) +echo_i "checking whether named calculates outgoing AXFR statistics correctly ($n)" tmp=1 for i in 0 1 2 3 4 5 6 7 8 9; do get_named_xfer_stats ns3/named.run 10.53.0.2 xfer-stats "AXFR ended" > stats.outgoing @@ -525,7 +528,7 @@ for i in 0 1 2 3 4 5 6 7 8 9; do sleep 1 done if test $tmp != 0 ; then echo_i "failed"; fi -status=`expr $status + $tmp` +status=$((status+tmp)) echo_i "exit status: $status" [ $status -eq 0 ] || exit 1