diff --git a/.github/workflows/build-and-make.yaml b/.github/workflows/build-and-make.yaml index da7003220..e31a370fc 100644 --- a/.github/workflows/build-and-make.yaml +++ b/.github/workflows/build-and-make.yaml @@ -1099,6 +1099,15 @@ jobs: sudo snap disconnect iptvnator:graphics-core22 mesa-core22:graphics-core22 snap connections iptvnator | awk \ '$2 == "iptvnator:graphics-core22" && $3 == "-" { found=1 } END { exit !found }' + probe_timed_out() { + # GNU timeout exits 124 when SIGTERM ends the app and 137 when -k + # escalates to SIGKILL. --verbose announces that KILL, so an app + # killed by anything else is not misreported as a timeout. + local status="$1" output="$2" + [ "${status}" -eq 124 ] && return 0 + [ "${status}" -eq 137 ] && + grep -Fq 'sending signal KILL to command' <<<"${output}" + } # GNU timeout kills a packaged app that never exits, for example when the # main process throws before app ready and Electron's uncaught-exception # dialog blocks under xvfb. ELECTRON_ENABLE_LOGGING routes Chromium and @@ -1107,13 +1116,13 @@ jobs: set +e disconnected_probe="$( xvfb-run -a env LIBGL_ALWAYS_SOFTWARE=1 ELECTRON_ENABLE_LOGGING=1 \ - timeout -k 10 300 \ + timeout --verbose -k 10 300 \ snap run iptvnator --embedded-mpv-runtime-probe 2>&1 )" disconnected_status=$? set -e printf '%s\n' "${disconnected_probe}" - if [ "${disconnected_status}" -eq 124 ]; then + if probe_timed_out "${disconnected_status}" "${disconnected_probe}"; then echo "::error::The packaged Snap app did not exit within 300 seconds during the disconnected graphics runtime probe and was killed; inspect the probe output above for main-process startup errors." exit 1 fi @@ -1150,13 +1159,13 @@ jobs: XDG_CONFIG_DIRS=/tmp/hostile-xdg-config-dirs \ XDG_DATA_HOME=/tmp/hostile-xdg-data-home \ XDG_DATA_DIRS=/tmp/hostile-xdg-data-dirs \ - timeout -k 10 300 \ + timeout --verbose -k 10 300 \ snap run iptvnator --embedded-mpv-runtime-probe 2>&1 )" hostile_status=$? set -e printf '%s\n' "${hostile_probe}" - if [ "${hostile_status}" -eq 124 ]; then + if probe_timed_out "${hostile_status}" "${hostile_probe}"; then echo "::error::The packaged Snap app did not exit within 300 seconds during the hostile-environment runtime probe and was killed; inspect the probe output above for main-process startup errors." exit 1 fi @@ -1249,13 +1258,22 @@ jobs: ELF_MAGIC="$(od -An -tx1 -N4 "${LAUNCHER_PATH}" | tr -d "[:space:]")" test "${ELF_MAGIC}" = "7f454c46" ' + probe_timed_out() { + # GNU timeout exits 124 when SIGTERM ends the app and 137 when -k + # escalates to SIGKILL. --verbose announces that KILL, so an app + # killed by anything else is not misreported as a timeout. + local status="$1" output="$2" + [ "${status}" -eq 124 ] && return 0 + [ "${status}" -eq 137 ] && + grep -Fq 'sending signal KILL to command' <<<"${output}" + } # GNU timeout kills a packaged app that never exits, for example when the # main process throws before app ready and Electron's uncaught-exception # dialog blocks under xvfb. ELECTRON_ENABLE_LOGGING routes Chromium and # main-process stderr into the captured output. set +e PROBE_OUTPUT="$( - xvfb-run -a dbus-run-session -- timeout -k 10 300 flatpak run \ + xvfb-run -a dbus-run-session -- timeout --verbose -k 10 300 flatpak run \ --env=LIBGL_ALWAYS_SOFTWARE=1 \ --env=ELECTRON_ENABLE_LOGGING=1 \ com.fourgray.iptvnator \ @@ -1264,17 +1282,22 @@ jobs: PROBE_STATUS=$? set -e + # Keep both ends of oversized output: logging can push a startup + # exception or the timeout notice past the first window. PROBE_OUTPUT_LIMIT=16384 - printf '%s\n' "${PROBE_OUTPUT:0:PROBE_OUTPUT_LIMIT}" - if [ "${#PROBE_OUTPUT}" -gt "${PROBE_OUTPUT_LIMIT}" ]; then - echo "::warning::Flatpak runtime probe output was truncated to ${PROBE_OUTPUT_LIMIT} characters." + if [ "${#PROBE_OUTPUT}" -le $((PROBE_OUTPUT_LIMIT * 2)) ]; then + printf '%s\n' "${PROBE_OUTPUT}" + else + printf '%s\n' "${PROBE_OUTPUT:0:PROBE_OUTPUT_LIMIT}" + echo "::warning::Flatpak runtime probe output was truncated to its first and last ${PROBE_OUTPUT_LIMIT} characters." + printf '%s\n' "${PROBE_OUTPUT: -PROBE_OUTPUT_LIMIT}" fi if [[ "${PROBE_OUTPUT}" == *"not an ELF file"* ]] || [[ "${PROBE_OUTPUT}" == *"Zypak needs to be called directly"* ]]; then echo "::error::Flatpak launched a wrapper instead of the Electron ELF." exit 1 fi - if [ "${PROBE_STATUS}" -eq 124 ]; then + if probe_timed_out "${PROBE_STATUS}" "${PROBE_OUTPUT}"; then echo "::error::The packaged Flatpak app did not exit within 300 seconds during the application runtime probe and was killed; inspect the probe output above for main-process startup errors." exit 1 fi diff --git a/docs/development/electron-debugging.md b/docs/development/electron-debugging.md index 6354add30..f4ac23c2c 100644 --- a/docs/development/electron-debugging.md +++ b/docs/development/electron-debugging.md @@ -92,11 +92,12 @@ The Linux portable build uploads `packaged-frame-copy-smoke` reports and traces even when the smoke fails. Check the paused-frame screenshot and trace before classifying a zero rendered-frame signal as an infrastructure flake. The Snap and Flatpak `--embedded-mpv-runtime-probe` launches in -`build-and-make.yaml` run under GNU `timeout -k 10 300` with +`build-and-make.yaml` run under GNU `timeout --verbose -k 10 300` with `ELECTRON_ENABLE_LOGGING=1`, so a main process that throws before app ready and blocks on Electron's uncaught-exception dialog under xvfb fails within -five minutes with a distinct `::error::` for exit 124 and its stderr in the -step log, instead of holding the job until the 120-minute limit. +five minutes with a distinct `::error::` (exit 124, or 137 after timeout's +announced KILL escalation) and its stderr in the step log, instead of holding +the job until the 120-minute limit. ## Main-process ownership diff --git a/tools/packaging/configure-linux-frame-copy-build.test.mjs b/tools/packaging/configure-linux-frame-copy-build.test.mjs index 6bb83a4a0..785dcda5f 100644 --- a/tools/packaging/configure-linux-frame-copy-build.test.mjs +++ b/tools/packaging/configure-linux-frame-copy-build.test.mjs @@ -561,7 +561,7 @@ test('Flatpak application runtime probe runs under an isolated D-Bus session', ( assert.match( flatpakVerificationStep, - /xvfb-run -a dbus-run-session -- timeout -k 10 300 flatpak run\s+\\\s+--env=LIBGL_ALWAYS_SOFTWARE=1\s+\\\s+--env=ELECTRON_ENABLE_LOGGING=1\s+\\\s+com\.fourgray\.iptvnator\s+\\\s+--embedded-mpv-runtime-probe/ + /xvfb-run -a dbus-run-session -- timeout --verbose -k 10 300 flatpak run\s+\\\s+--env=LIBGL_ALWAYS_SOFTWARE=1\s+\\\s+--env=ELECTRON_ENABLE_LOGGING=1\s+\\\s+com\.fourgray\.iptvnator\s+\\\s+--embedded-mpv-runtime-probe/ ); assert.match(installStep, /^\s+dbus-daemon\s+\\$/m); assert.match( @@ -602,7 +602,7 @@ test('Flatpak CI verifies the direct Zypak ELF and preserves probe status', () = assert.match( flatpakVerificationStep, - /set \+e[\s\S]*PROBE_OUTPUT="\$\([\s\S]*xvfb-run -a dbus-run-session -- timeout -k 10 300 flatpak run[\s\S]*--embedded-mpv-runtime-probe 2>&1[\s\S]*\)"[\s\S]*PROBE_STATUS=\$\?[\s\S]*set -e/ + /set \+e[\s\S]*PROBE_OUTPUT="\$\([\s\S]*xvfb-run -a dbus-run-session -- timeout --verbose -k 10 300 flatpak run[\s\S]*--embedded-mpv-runtime-probe 2>&1[\s\S]*\)"[\s\S]*PROBE_STATUS=\$\?[\s\S]*set -e/ ); assert.match( flatpakVerificationStep, @@ -624,9 +624,12 @@ test('packaged runtime probes are time-boxed and report a hung app distinctly', 'Verify Flatpak payload, launcher, and sandboxed runtime' ); const probeInvocation = - /timeout -k 10 300 \\\s+snap run iptvnator --embedded-mpv-runtime-probe 2>&1/g; + /timeout --verbose -k 10 300 \\\s+snap run iptvnator --embedded-mpv-runtime-probe 2>&1/g; const timeoutFailure = - /if \[ "\$\{(\w+)\}" -eq 124 \]; then\s+echo "::error::[^"]*did not exit within 300 seconds[^"]*"\s+exit 1\s+fi/g; + /if probe_timed_out "\$\{(\w+)\}" "\$\{\w+\}"; then\s+echo "::error::[^"]*did not exit within 300 seconds[^"]*"\s+exit 1\s+fi/g; + // 124 is SIGTERM; 137 counts only when timeout announced its own KILL. + const timeoutClassifier = + /probe_timed_out\(\) \{[\s\S]*?\[ "\$\{status\}" -eq 124 \] && return 0\s+\[ "\$\{status\}" -eq 137 \] &&\s+grep -Fq 'sending signal KILL to command' <<<"\$\{output\}"\s+\}/; // Every `snap run` probe is wrapped by GNU timeout and captured, so a // blocked uncaught-exception dialog cannot hold the job until its @@ -639,18 +642,24 @@ test('packaged runtime probes are time-boxed and report a hung app distinctly', assert.equal(snapStep.match(probeInvocation).length, 2); assert.match( snapStep, - /disconnected_probe="\$\([\s\S]*ELECTRON_ENABLE_LOGGING=1[\s\S]*timeout -k 10 300[\s\S]*\)"\s+disconnected_status=\$\?\s+set -e\s+printf '%s\\n' "\$\{disconnected_probe\}"/ + /disconnected_probe="\$\([\s\S]*ELECTRON_ENABLE_LOGGING=1[\s\S]*timeout --verbose -k 10 300[\s\S]*\)"\s+disconnected_status=\$\?\s+set -e\s+printf '%s\\n' "\$\{disconnected_probe\}"/ ); assert.match( snapStep, - /hostile_probe="\$\([\s\S]*ELECTRON_ENABLE_LOGGING=1[\s\S]*timeout -k 10 300[\s\S]*\)"\s+hostile_status=\$\?\s+set -e\s+printf '%s\\n' "\$\{hostile_probe\}"/ + /hostile_probe="\$\([\s\S]*ELECTRON_ENABLE_LOGGING=1[\s\S]*timeout --verbose -k 10 300[\s\S]*\)"\s+hostile_status=\$\?\s+set -e\s+printf '%s\\n' "\$\{hostile_probe\}"/ ); assert.deepEqual( [...snapStep.matchAll(timeoutFailure)].map(([, variable]) => variable), ['disconnected_status', 'hostile_status'] ); + assert.match(snapStep, timeoutClassifier); assert.ok( - snapStep.indexOf('-eq 124') < + snapStep.indexOf('probe_timed_out() {') < + snapStep.indexOf('disconnected_probe="$('), + 'the timeout classifier must be defined before the first probe' + ); + assert.ok( + snapStep.indexOf('if probe_timed_out "${disconnected_status}"') < snapStep.indexOf('test "${disconnected_status}" -eq 1'), 'the disconnected probe must reject a timeout before asserting exit 1' ); @@ -658,6 +667,11 @@ test('packaged runtime probes are time-boxed and report a hung app distinctly', snapStep, /if \[ "\$\{hostile_status\}" -ne 0 \]; then[\s\S]*exit "\$\{hostile_status\}"/ ); + assert.ok( + snapStep.indexOf('if probe_timed_out "${hostile_status}"') < + snapStep.indexOf('if [ "${hostile_status}" -ne 0 ]'), + 'the hostile probe must report a timeout before its generic status failure' + ); assert.ok( snapStep.includes( `grep -Fx '{"usable":false,"reason":"snap-graphics-provider-unavailable"}'` @@ -666,7 +680,9 @@ test('packaged runtime probes are time-boxed and report a hung app distinctly', ); assert.equal( - flatpakVerificationStep.match(/timeout -k 10 300 flatpak run/g).length, + flatpakVerificationStep.match( + /timeout --verbose -k 10 300 flatpak run/g + ).length, 1 ); assert.deepEqual( @@ -675,9 +691,22 @@ test('packaged runtime probes are time-boxed and report a hung app distinctly', ), ['PROBE_STATUS'] ); + assert.match(flatpakVerificationStep, timeoutClassifier); assert.ok( - flatpakVerificationStep.indexOf('-eq 124') < - flatpakVerificationStep.indexOf('if [ "${PROBE_STATUS}" -ne 0 ]'), + flatpakVerificationStep.indexOf('probe_timed_out() {') < + flatpakVerificationStep.indexOf('PROBE_OUTPUT="$('), + 'the timeout classifier must be defined before the Flatpak probe' + ); + // Oversized output keeps its tail, where a late exception or the + // timeout notice lands. + assert.match( + flatpakVerificationStep, + /if \[ "\$\{#PROBE_OUTPUT\}" -le \$\(\(PROBE_OUTPUT_LIMIT \* 2\)\) \]; then\s+printf '%s\\n' "\$\{PROBE_OUTPUT\}"\s+else\s+printf '%s\\n' "\$\{PROBE_OUTPUT:0:PROBE_OUTPUT_LIMIT\}"[\s\S]*?printf '%s\\n' "\$\{PROBE_OUTPUT: -PROBE_OUTPUT_LIMIT\}"\s+fi/ + ); + assert.ok( + flatpakVerificationStep.indexOf( + 'if probe_timed_out "${PROBE_STATUS}"' + ) < flatpakVerificationStep.indexOf('if [ "${PROBE_STATUS}" -ne 0 ]'), 'the timeout verdict must precede the generic non-zero status handling' ); });