diff --git a/frame/DEV.md b/frame/DEV.md index afa8cbc..c3d249d 100644 --- a/frame/DEV.md +++ b/frame/DEV.md @@ -232,3 +232,11 @@ every end against its refresh's update window (before / inside / after, SteamVR' prints the game's lines. Mock: mockrun.sh runs the helper against frame/tools/openvr-stub.c (STUB_UPDATE_MS, KF_MOCKRUN_STUB_UPDATE_MS, KF_MOCKRUN_PHASE_SECONDS) with MOCK_XR_ALIGN_US. Analysis: frame/perf/LANE_X.md; next session: frame/perf/session-h20/README.md. + +## Wrapper recorder (KARTFRAME_RECORD) +The recorder starts 8 s after the game and only if the game is still alive then; it runs in its own +session (setsid) and the wrapper stops it on every exit path (game exit, Steam's TERM/INT/HUP): SIGINT +and up to 30 s for the file, then TERM, then KILL, then a pkill on anything writing into the session's +panels.mkv. The log says "recorder stopped" or "recorder was never started"; a leftover +panels.mkv.part is logged with its size and left for the owner. frame/test-wrapper-recorder.sh checks +the four paths with a fake game and a fake framecorder (about 45 s). diff --git a/frame/kartframe.sh b/frame/kartframe.sh index c8e9e5d..3305384 100755 --- a/frame/kartframe.sh +++ b/frame/kartframe.sh @@ -148,24 +148,71 @@ GAME_PID=$! echo "kartframe $GAME_PID" > "$HEADSET_MARK" 2> /dev/null # KARTFRAME_RECORD=raw records both panels as scanned out (framecorder; about 1.6 ms of GPU a frame) # into the session folder, for questions the logs cannot settle (per-eye ghosting, flicker). +# The recorder starts 8 s in and only if the game is still there then (it once started after a game +# that had died at 3 s and recorded the headset for hours). It runs in its own session (setsid), so +# stopping it can reach everything it started (the framecorder-grab helper too). .rec-started marks +# that it really began. REC_PID= # Steam starts games with a short PATH (no ~/.local/bin), so look for the recorder by its full path too. FRAMECORDER=$(command -v framecorder 2> /dev/null || ls "$HOME/.local/bin/framecorder" 2> /dev/null) if [ -n "$KARTFRAME_RECORD" ] && [ -z "$FRAMECORDER" ]; then log "RECORDING NOT POSSIBLE: framecorder not found"; fi if [ -n "$KARTFRAME_RECORD" ] && [ -n "$FRAMECORDER" ]; then - ( sleep 8; exec "$FRAMECORDER" --view "${KARTFRAME_RECORD}" --fps "${KARTFRAME_RECORD_FPS:-120}" --qp 18 "$SESSION/panels.mkv" ) \ + rm -f "$SESSION/.rec-started" + setsid bash -c 'for ((i = 0; i < 80; i++)); do kill -0 "$1" 2> /dev/null || exit 0; sleep 0.1; done + touch "$2/.rec-started"; shift 2; exec "$@"' _ "$GAME_PID" "$SESSION" \ + "$FRAMECORDER" --view "${KARTFRAME_RECORD}" --fps "${KARTFRAME_RECORD_FPS:-120}" --qp 18 "$SESSION/panels.mkv" \ > "$SESSION/framecorder.log" 2>&1 & REC_PID=$! log "recording the panels (framecorder --view $KARTFRAME_RECORD) into panels.mkv" fi -trap 'kill -TERM "$GAME_PID" 2> /dev/null' TERM INT HUP +# Anything of the recorder still alive (a finished process that nobody has waited for does not count). +rec_alive() { + ps -o stat= --sid "$REC_PGID" 2> /dev/null | grep -q '^[^Z]' || + pgrep -f "framecorder .* $SESSION/panels.mkv" > /dev/null +} +# Stops the recorder in every case: not started yet (the waiting subshell is killed and never starts it), +# running (SIGINT to finish the file, then a bounded wait, then TERM and KILL). Runs once. +stop_recorder() { + [ -n "$REC_PID" ] || return 0 + REC_PGID=$REC_PID; REC_PID= + local n how=stopped + if [ -f "$SESSION/.rec-started" ]; then + kill -INT "$REC_PGID" 2> /dev/null + for ((n = 0; n < 300; n++)); do rec_alive || break; sleep 0.1; done # up to 30 s to finish the file + if rec_alive; then + how="stopped after TERM (SIGINT did not finish it)" + kill -TERM -- "-$REC_PGID" 2> /dev/null; pkill -TERM -s "$REC_PGID" 2> /dev/null + pkill -TERM -f "framecorder .* $SESSION/panels.mkv" 2> /dev/null + for ((n = 0; n < 50; n++)); do rec_alive || break; sleep 0.1; done + fi + if rec_alive; then + how="killed (SIGINT and TERM did not stop it)" + kill -KILL -- "-$REC_PGID" 2> /dev/null; pkill -KILL -s "$REC_PGID" 2> /dev/null + pkill -KILL -f "framecorder .* $SESSION/panels.mkv" 2> /dev/null + sleep 0.5 + fi + wait "$REC_PGID" 2> /dev/null + rec_alive && log "WARNING: a recorder process is still alive for $SESSION/panels.mkv" + log "recorder $how" + else + kill -TERM "$REC_PGID" 2> /dev/null; kill -TERM -- "-$REC_PGID" 2> /dev/null + pkill -TERM -s "$REC_PGID" 2> /dev/null + wait "$REC_PGID" 2> /dev/null + log "recorder was never started (the game was gone before the 8 s were up)" + fi + # A leftover part file is the owner's to judge: logged, never deleted. + if [ -f "$SESSION/panels.mkv.part" ] && ! rec_alive; then + log "panels.mkv.part left in the session folder, $(stat -c %s "$SESSION/panels.mkv.part") bytes, no recorder alive" + fi +} +trap 'kill -TERM "$GAME_PID" 2> /dev/null; stop_recorder' TERM INT HUP rc=0 while kill -0 "$GAME_PID" 2> /dev/null; do wait "$GAME_PID"; rc=$? done trap - TERM INT HUP rm -f "$HEADSET_MARK" -[ -n "$REC_PID" ] && { pkill -INT -P "$REC_PID" framecorder 2> /dev/null; kill -INT "$REC_PID" 2> /dev/null; sleep 3; } +stop_recorder log "game exited with status $rc" [ -n "$VRT_PID" ] && { kill "$VRT_PID" 2> /dev/null; wait "$VRT_PID" 2> /dev/null; } diff --git a/frame/test-wrapper-recorder.sh b/frame/test-wrapper-recorder.sh new file mode 100755 index 0000000..b50cae5 --- /dev/null +++ b/frame/test-wrapper-recorder.sh @@ -0,0 +1,95 @@ +#!/bin/bash +# Test for the panel recorder handling in kartframe.sh (KARTFRAME_RECORD): the game dies early, the +# game ends normally, the wrapper is killed. Touches nothing real: a scratch KARTFRAME_HOME, HOME and +# cache, a fake game, a fake framecorder (and framecorder-grab) first on PATH. No Steam, no SteamVR. +# frame/test-wrapper-recorder.sh [SCRATCH_DIR] (default ~/.cache/kf-test-wrapper-recorder, emptied first) +HERE=$(cd "$(dirname "$0")" && pwd) +T=${1:-$HOME/.cache/kf-test-wrapper-recorder} +rm -rf "$T"; mkdir -p "$T/bin" "$T/home" "$T/cache" +fails=0 +ok() { echo "ok $*"; } +bad() { echo "FAIL $*"; fails=$((fails + 1)); } +check() { local d=$1; shift; if "$@"; then ok "$d"; else bad "$d"; fi; } + +# A game that lives N seconds (exec, so a TERM ends it). +printf '#!/bin/bash\necho $$ > "$KARTFRAME_HOME/game.pid"\nexec sleep "${FAKE_GAME_SECONDS:-1}"\n' > "$T/game" +# The recorder's helper: runs until killed. +printf '#!/bin/bash\nwhile :; do sleep 1; done\n' > "$T/bin/framecorder-grab" +# The recorder: grows panels.mkv.part, takes SIGINT to finish the file (python, as a signal handler +# must be installed explicitly: a background job of the wrapper starts with SIGINT ignored). +cat > "$T/bin/framecorder" << 'PY' +#!/usr/bin/python3 -I +import os, signal, subprocess, sys, time +out = sys.argv[-1] +grab = subprocess.Popen([os.path.join(os.path.dirname(os.path.realpath(__file__)), "framecorder-grab")]) +stop = [] +signal.signal(signal.SIGINT, lambda *a: stop.append(1)) +f = open(out + ".part", "wb") +print("fake framecorder started", flush=True) +while not stop: + f.write(b"x" * 4096); f.flush(); time.sleep(0.1) +print("fake framecorder got SIGINT, finishing", flush=True) +time.sleep(1) +f.close(); os.rename(out + ".part", out) +grab.terminate(); grab.wait() +print("fake framecorder finished the file", flush=True) +PY +chmod +x "$T/game" "$T/bin/framecorder" "$T/bin/framecorder-grab" + +survivors() { pgrep -f "$T/bin/framecorder" | tr '\n' ' '; } +# run NAME GAME_SECONDS: starts the wrapper in the background; WRAP_PID, KFH (its KARTFRAME_HOME) +run() { + KFH=$T/$1; mkdir -p "$KFH" + ( cd "$T" && exec env -u SteamAppId HOME="$T/home" XDG_CACHE_HOME="$T/cache" PATH="$T/bin:$PATH" \ + KARTFRAME_HOME="$KFH" KARTFRAME_EXE="$T/game" FAKE_GAME_SECONDS="$2" KARTFRAME_VRTIMING=0 \ + KARTFRAME_RECORD=raw bash "$HERE/kartframe.sh" ) > "$T/$1.out" 2>&1 & + WRAP_PID=$! +} +waitfor() { # waitfor PID SECONDS: true when PID is gone in time + local n; for ((n = 0; n < $2 * 10; n++)); do kill -0 "$1" 2> /dev/null || return 0; sleep 0.1; done; return 1 +} +LOG() { echo "$KFH/sessions/latest/launch.log"; } +show() { echo " --- launch.log (recorder lines)"; grep -i 'record\|panels\|game exited' "$KFH/sessions/latest/launch.log" | sed 's/^/ /'; } + +echo "== 1: game exits after 1 s, before the recorder's 8 s ==" +run early 1 +check "wrapper finished" waitfor "$WRAP_PID" 30 +sleep 9 # past the point where the old wrapper's recorder started anyway +check "no recorder process survives (survivors: $(survivors))" test -z "$(survivors)" +check "log says it was never started" grep -q 'recorder was never started' "$(LOG)" +check "no panels.mkv.part" test ! -e "$KFH/sessions/latest/panels.mkv.part" +show + +echo "== 2: game runs 12 s, recorder runs, game exits normally ==" +run normal 12 +check "wrapper finished" waitfor "$WRAP_PID" 60 +check "no recorder process survives (survivors: $(survivors))" test -z "$(survivors)" +check "log says recorder stopped" grep -q 'recorder stopped' "$(LOG)" +check "recorder got SIGINT and finished the file" grep -q 'finished the file' "$KFH/sessions/latest/framecorder.log" +check "panels.mkv exists, no .part left" test -s "$KFH/sessions/latest/panels.mkv" -a ! -e "$KFH/sessions/latest/panels.mkv.part" +show + +echo "== 3: wrapper killed with TERM while the game runs (recorder up) ==" +run killed 60 +sleep 10 +check "recorder is running before the kill" test -n "$(survivors)" +kill -TERM "$WRAP_PID" +check "wrapper finished" waitfor "$WRAP_PID" 30 +check "no recorder process survives (survivors: $(survivors))" test -z "$(survivors)" +check "game is gone" test ! -d "/proc/$(cat "$KFH/game.pid")" +check "log says recorder stopped" grep -q 'recorder stopped' "$(LOG)" +show + +echo "== 4: wrapper killed with TERM before the recorder started ==" +run killedearly 60 +sleep 3 +kill -TERM "$WRAP_PID" +check "wrapper finished" waitfor "$WRAP_PID" 30 +sleep 7 +check "no recorder process survives (survivors: $(survivors))" test -z "$(survivors)" +check "log says it was never started" grep -q 'recorder was never started' "$(LOG)" +show + +echo +[ "$fails" = 0 ] && echo "all passed" || echo "$fails FAILED" +exit $((fails > 0))