Many OVS tests wait up for 10 seconds for a condition to become true. Usually these conditions are ones that should take only a second or so to actually become true in practice, but on a busy and slow machine it's possible that some tests might fail or come close to failing because 10 seconds is simply not enough there.
This commit adds logging for the case where a condition actually succeeds to indicate the amount of time that was waited. This should make it easier to identify whether we need to increase the maximum wait time from 10 seconds to something longer, by allowing us to see whether some of the successful waits came close to timing out. Reported-by: Thomas Goirand <z...@debian.org> Reported-at: https://mail.openvswitch.org/pipermail/ovs-discuss/2018-September/047340.html Signed-off-by: Ben Pfaff <b...@ovn.org> --- tests/ovn.at | 15 ++++++++------- tests/ovs-macros.at | 53 +++++++++++++++++++++++++++++------------------------ 2 files changed, 37 insertions(+), 31 deletions(-) diff --git a/tests/ovn.at b/tests/ovn.at index e10a7f9bab59..8728084e51fd 100644 --- a/tests/ovn.at +++ b/tests/ovn.at @@ -17,13 +17,11 @@ m4_divert_text([PREPARE_TESTS], rcv_text=`echo "$rcv_pcap.packets" | sed 's/\.pcap//'` exp_text=$2 exp_n=`wc -l < "$exp_text"` - ovs_wait_cond () { - $PYTHON "$top_srcdir/utilities/ovs-pcap.in" $rcv_pcap > $rcv_text - rcv_n=`wc -l < "$rcv_text"` - test $rcv_n -ge $exp_n - } - ovs_wait || echo "expected $exp_n packets, only received $rcv_n" - + OVS_WAIT_UNTIL( + [$PYTHON "$top_srcdir/utilities/ovs-pcap.in" $rcv_pcap > $rcv_text + rcv_n=`wc -l < "$rcv_text"` + echo "rcv_n=$rcv_n exp_n=$exp_n" + test $rcv_n -ge $exp_n]) sort $exp_text > expout } ]) @@ -4290,6 +4288,9 @@ test_dhcp() { # dhcp message type request=${request}3501${dhcp_type}ff + for port in $inport "$@"; do + : >> $port.expected + done if test $offer_ip != 0; then local srv_mac=$1 srv_ip=$2 expected_dhcp_opts=$3 # total IP length will be the IP length of the request packet diff --git a/tests/ovs-macros.at b/tests/ovs-macros.at index 066c25ccbd82..48f0892ff0de 100644 --- a/tests/ovs-macros.at +++ b/tests/ovs-macros.at @@ -48,24 +48,6 @@ ovs_setenv() { OVS_PKGDATADIR=$ovs_dir; export OVS_PKGDATADIR } -ovs_wait () { - # First try the condition without waiting. - ovs_wait_cond && return 0 - - # Try a quick sleep, so that the test completes very quickly - # in the normal case. POSIX doesn't require fractional times to - # work, so this might not work. - sleep 0.1 - ovs_wait_cond && return 0 - - # Then wait up to 10 seconds. - for d in 0 1 2 3 4 5 6 7 8 9; do - sleep 1 - ovs_wait_cond && return 0 - done - return 1 -} - # Prints the integers from $1 to $2, increasing by $3 (default 1) on stdout. seq () { if test $# = 1; then @@ -197,17 +179,40 @@ fi ] m4_divert_pop([PREPARE_TESTS]) +OVS_START_SHELL_HELPERS +ovs_wait () { + echo "$1: waiting $2..." >&AS_MESSAGE_LOG_FD + + # First try the condition without waiting. + if ovs_wait_cond; then echo "$1: immediate success" >&AS_MESSAGE_LOG_FD; return 0; fi + + # Try a quick sleep, so that the test completes very quickly + # in the normal case. POSIX doesn't require fractional times to + # work, so this might not work. + sleep 0.1 + if ovs_wait_cond; then echo "$1: quick success" >&AS_MESSAGE_LOG_FD; return 0; fi + + # Then wait up to 10 seconds. + local d + for d in 1 2 3 4 5 6 7 8 9 10; do + sleep 1 + if ovs_wait_cond; then echo "$1: success after $d seconds" >&AS_MESSAGE_LOG_FD; return 0; fi + done + + echo "$1: wait failed" >&AS_MESSAGE_LOG_FD + ovs_wait_failed + AT_FAIL_IF([:]) +} +OVS_END_SHELL_HELPERS m4_define([OVS_WAIT], [dnl -AS_ECHO(["AS_ESCAPE([$3: waiting $4...])"]) >&AS_MESSAGE_LOG_FD ovs_wait_cond () { $1 } -if ovs_wait; then : -else - AS_ECHO(["AS_ESCAPE([$3: wait failed])"]) >&AS_MESSAGE_LOG_FD +ovs_wait_failed () { + : $2 - AT_FAIL_IF([:]) -fi +} +ovs_wait "AS_ESCAPE([$3])" "AS_ESCAPE([$4])" ]) dnl OVS_WAIT_UNTIL(COMMAND) -- 2.16.1 _______________________________________________ dev mailing list d...@openvswitch.org https://mail.openvswitch.org/mailman/listinfo/ovs-dev
