diff --git a/smoketest/lib/scenario.sh b/smoketest/lib/scenario.sh index 5e75cc3..d3434e8 100644 --- a/smoketest/lib/scenario.sh +++ b/smoketest/lib/scenario.sh @@ -48,17 +48,36 @@ skip() { # run_in_vm NAME SCRIPT: run SCRIPT in the VM, keeping its output in $OUTPUT, # its exit status in $STATUS, and both in NN-NAME.log. Doesn't fail on its own: # check with assert_status. The log is written as SCRIPT runs, so a long one -# (install.sh takes an hour or more) can be followed with tail -f. +# (install.sh takes an hour or more) can be followed with tail -f, and once a +# minute run_in_vm says it's still running, with the log's latest line. run_in_vm() { + local ticker RUN_COUNT=$((RUN_COUNT + 1)) LAST_RUN="$1" LAST_LOG="$SMOKETEST_RESULTS/$(printf '%02d' "$RUN_COUNT")-$1.log" echo "== $1 (to follow it: tail -f $LAST_LOG)" + : > "$LAST_LOG" + progress_ticker "$1" "$LAST_LOG" & + ticker=$! vm_exec "$2" > "$LAST_LOG" 2>&1 && STATUS=0 || STATUS=$? + kill "$ticker" 2> /dev/null + wait "$ticker" 2> /dev/null || true OUTPUT="$(cat "$LAST_LOG")" echo "== $1 exited $STATUS (log: $LAST_LOG)" } +# progress_ticker NAME LOG: every SMOKETEST_TICK seconds (60), say NAME is +# still running, for how long, and LOG's latest line. run_in_vm kills it. +# sleep gets no stdout, so a killed ticker leaves nothing holding the driver's +# pipe to tee open. +progress_ticker() { + local start=$SECONDS tick="${SMOKETEST_TICK:-60}" last + while sleep "$tick" > /dev/null 2>&1 3>&-; do + last="$(tail -c 4096 "$2" | tr '\r' '\n' | grep -v '^[[:space:]]*$' | tail -n 1 | cut -c 1-100)" + echo " still running $1 ($(( (SECONDS - start) / 60 )) min)${last:+: $last}" + done +} + # Called by the driver once the VM is up, before the scenario smoketest_prepare() { local urls="" url diff --git a/tests/smoketest.bats b/tests/smoketest.bats index 8352d04..0f9b40a 100644 --- a/tests/smoketest.bats +++ b/tests/smoketest.bats @@ -138,6 +138,14 @@ upstream_main() { [ -f "$SMOKETEST_RESULTS/02-second.log" ] } +@test "run_in_vm says once a tick that it's still running, with the log's latest line" { + export SMOKETEST_TICK=1 + run run_in_vm slow 'echo working; sleep 2.5' + [ "$status" -eq 0 ] + [[ "$output" == *" still running slow (0 min): working"* ]] + [[ "$output" == *"== slow exited 0 (log: "* ]] +} + @test "run_in_vm writes its log while the script runs" { run_in_vm slow 'echo early; cat "$SMOKETEST_RESULTS/01-slow.log" > "$HOME/seen"' [ "$STATUS" -eq 0 ]