Merge branch 'lane/Z' into native

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).

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; }
 

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))