smoketest: say once a minute that a command in the VM is still running
run_in_vm prints how long it has run and the log's latest line, so an hour-long install.sh shows progress without tail -f. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
@@ -48,17 +48,36 @@ skip() {
|
|||||||
# run_in_vm NAME SCRIPT: run SCRIPT in the VM, keeping its output in $OUTPUT,
|
# 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:
|
# 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
|
# 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() {
|
run_in_vm() {
|
||||||
|
local ticker
|
||||||
RUN_COUNT=$((RUN_COUNT + 1))
|
RUN_COUNT=$((RUN_COUNT + 1))
|
||||||
LAST_RUN="$1"
|
LAST_RUN="$1"
|
||||||
LAST_LOG="$SMOKETEST_RESULTS/$(printf '%02d' "$RUN_COUNT")-$1.log"
|
LAST_LOG="$SMOKETEST_RESULTS/$(printf '%02d' "$RUN_COUNT")-$1.log"
|
||||||
echo "== $1 (to follow it: tail -f $LAST_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=$?
|
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")"
|
OUTPUT="$(cat "$LAST_LOG")"
|
||||||
echo "== $1 exited $STATUS (log: $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
|
# Called by the driver once the VM is up, before the scenario
|
||||||
smoketest_prepare() {
|
smoketest_prepare() {
|
||||||
local urls="" url
|
local urls="" url
|
||||||
|
|||||||
@@ -138,6 +138,14 @@ upstream_main() {
|
|||||||
[ -f "$SMOKETEST_RESULTS/02-second.log" ]
|
[ -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" {
|
@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"'
|
run_in_vm slow 'echo early; cat "$SMOKETEST_RESULTS/01-slow.log" > "$HOME/seen"'
|
||||||
[ "$STATUS" -eq 0 ]
|
[ "$STATUS" -eq 0 ]
|
||||||
|
|||||||
Reference in New Issue
Block a user