From 1892b130ce23e6d973f49d9b4fe49c69fce2ce9c Mon Sep 17 00:00:00 2001 From: Daniel Han Date: Wed, 29 Jul 2026 04:44:54 +0000 Subject: [PATCH] Fail the leg when the signal landed after the marked step The cut-short added last round only helps when the marked step is still the last [TAURI:STEP] line at the moment the poll notices it. Creating the venv takes ~0.1s (staging run 30419729244: 03:31:07.371 -> 07.478), less than the 0.5s poll, so the next step's line is usually already in the log when the marker matches, the step count never changes during the beat, and the full 3s elapses inside "Installing PyTorch". Reproduced with a stub installer against the driver at head: kill at 4.11s, step at kill "Installing PyTorch". The leg then duplicates the torch leg while its matrix label claims the venv step, and passed green on nothing but a ::warning::. Both drivers now skip the beat entirely when the marked step is already over, so the kill goes out at once instead of deeper into the next step, and both record interrupt_step_mismatch in interrupt.env. The landing assertion fails on it: a warning that cannot fail the leg proves nothing. Sub-step markers ("studio deps", "pip bootstrap") print no step line of their own and stay exempt, as before. The venv leg becomes experimental. Its step is shorter than any log poll can resolve, so it must not block the PR on a race it cannot win, and it still probes the earliest torn state whenever it does land. --- .github/scripts/interrupt-install.ps1 | 41 +++++++++++++++----- .github/scripts/interrupt-install.sh | 36 ++++++++++++----- .github/workflows/interrupted-install-ci.yml | 28 ++++++++++++- 3 files changed, 86 insertions(+), 19 deletions(-) diff --git a/.github/scripts/interrupt-install.ps1 b/.github/scripts/interrupt-install.ps1 index 7200c1f5f7..1d8ac91ae1 100644 --- a/.github/scripts/interrupt-install.ps1 +++ b/.github/scripts/interrupt-install.ps1 @@ -69,6 +69,22 @@ function Get-StepCount([string]$Path) { @(Select-String -Path $Path -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue).Count } +function Get-LastStep([string]$Path) { + $steps = @(Select-String -Path $Path -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue) + if ($steps.Count) { return $steps[-1].Line } + return '' +} + +# True when the marker names a [TAURI:STEP] line that is no longer the last one: the step +# ended before the poll noticed it. Sub-step markers ('studio deps') print no step line of +# their own, so they are never judged here. +function Test-MarkedStepOver { + if (-not $Marker) { return $false } + $steps = @(Select-String -Path $LogPath -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue) + if (-not ($steps | Where-Object { $_.Line -match $Marker })) { return $false } + return ((Get-LastStep $LogPath) -notmatch $Marker) +} + $killed = $false $reason = '' # Half-second slices: a step lasting under a second is over by the time a 1s poll notices @@ -80,12 +96,16 @@ for ($i = 0; $i -lt ($KillAtSeconds * 2); $i++) { if ($hit) { # Same beat as the POSIX driver, waited in slices and cut short once a later # [TAURI:STEP] line appears, so a fast step finishing inside the beat does not send - # the signal into the step after it. - $stepsAtMarker = Get-StepCount $LogPath - for ($j = 0; $j -lt ($KillAfterMarkerSeconds * 5); $j++) { - Start-Sleep -Milliseconds 200 - if ($proc.HasExited) { break } - if ((Get-StepCount $LogPath) -ne $stepsAtMarker) { break } + # the signal into the step after it. Skipped when the step is ALREADY over: the + # cut-short cannot help once the next step's line is in the log before the first + # sample, and beating on would push the signal deeper into the following step. + if (-not (Test-MarkedStepOver)) { + $stepsAtMarker = Get-StepCount $LogPath + for ($j = 0; $j -lt ($KillAfterMarkerSeconds * 5); $j++) { + Start-Sleep -Milliseconds 200 + if ($proc.HasExited) { break } + if ((Get-StepCount $LogPath) -ne $stepsAtMarker) { break } + } } # The installer can finish inside the delay; recording marker-hit before it # let a COMPLETED install satisfy the landing assertion and probe HEALTHY. @@ -136,15 +156,18 @@ if ($Marker -and -not (Select-String -Path $LogPath -Pattern $Marker -ErrorActio # poll notices its line, and the leg then silently kills the NEXT step while its matrix # label still claims the marked one. Sub-step markers ('studio deps') print no # [TAURI:STEP] line of their own, so the test skips them rather than warning every leg. -$steps = @(Select-String -Path $LogPath -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue) -$lastStep = if ($steps.Count) { $steps[-1].Line } else { '' } +$lastStep = Get-LastStep $LogPath Write-Host "[interrupt] step at kill: $lastStep" -if ($Marker -and ($steps | Where-Object { $_.Line -match $Marker }) -and $lastStep -notmatch $Marker) { +$mismatch = Test-MarkedStepOver +if ($mismatch) { Write-Host "::warning::killed in '$lastStep', not the marked step -- that step was already over" } +# Lower-cased so the workflow can compare it the same way on every platform, and only +# simple values: the POSIX side sources this file. @( "interrupt_reason=$reason" "interrupt_killed=$killed" "installer_exit=$rc" + "interrupt_step_mismatch=$(if ($mismatch) { 'true' } else { 'false' })" ) | Set-Content -Path (Join-Path (Split-Path -Parent $LogPath) 'interrupt.env') -Encoding utf8 exit 0 diff --git a/.github/scripts/interrupt-install.sh b/.github/scripts/interrupt-install.sh index 772481ccd0..f175758540 100755 --- a/.github/scripts/interrupt-install.sh +++ b/.github/scripts/interrupt-install.sh @@ -41,6 +41,16 @@ PID=$! set +m echo "[interrupt] installer pid/pgid=$PID marker='${MARKER}' deadline=${KILL_AT_SECONDS}s" +# True when the marker names a [TAURI:STEP] line that is no longer the last one: the step +# ended before the poll noticed it. Sub-step markers ("studio deps") print no step line of +# their own, so they are never judged here. +marked_step_over() { + [ -n "$MARKER" ] || return 1 + grep -E '^\[TAURI:STEP\]' "$LOG" 2>/dev/null | grep -qE "$MARKER" || return 1 + grep -E '^\[TAURI:STEP\]' "$LOG" 2>/dev/null | tail -1 | grep -qE "$MARKER" && return 1 + return 0 +} + killed=false reason="" # Half-second slices: a sub-second step is over before a 1s poll sees its line. @@ -54,12 +64,18 @@ for i in $(seq 1 $(( KILL_AT_SECONDS * 2 ))); do # [TAURI:STEP] line appears: the venv takes ~0.1s, so a flat 3s sleep put the venv # leg's signal in "Installing PyTorch", a duplicate of the torch leg. Sub-step # markers ("studio deps") print no step line, so they keep the whole beat. - _steps_at_marker="$(grep -cE '^\[TAURI:STEP\]' "$LOG" 2>/dev/null || true)" - for _ in $(seq 1 $(( ${KILL_AFTER_MARKER_SECONDS:-3} * 5 ))); do - sleep 0.2 - kill -0 "$PID" 2>/dev/null || break - [ "$(grep -cE '^\[TAURI:STEP\]' "$LOG" 2>/dev/null || true)" = "$_steps_at_marker" ] || break - done + # Skipped entirely when the step is ALREADY over: cutting the beat short cannot help + # once the next step's line is in the log before the first sample, which is the normal + # case for a 0.1s step, and beating on would only push the signal deeper into the step + # after it. Kill now and let the mismatch check below report where it landed. + if ! marked_step_over; then + _steps_at_marker="$(grep -cE '^\[TAURI:STEP\]' "$LOG" 2>/dev/null || true)" + for _ in $(seq 1 $(( ${KILL_AFTER_MARKER_SECONDS:-3} * 5 ))); do + sleep 0.2 + kill -0 "$PID" 2>/dev/null || break + [ "$(grep -cE '^\[TAURI:STEP\]' "$LOG" 2>/dev/null || true)" = "$_steps_at_marker" ] || break + done + fi # ...but a cached step can FINISH inside the beat. Recording marker-hit before it # handed the landing assertion a COMPLETED install that interrupted nothing. if ! kill -0 "$PID" 2>/dev/null; then @@ -120,14 +136,16 @@ fi # markers print no [TAURI:STEP] line, so the test skips them instead of always warning. _last_step="$(grep -E '^\[TAURI:STEP\]' "$LOG" 2>/dev/null | tail -1)" echo "[interrupt] step at kill: $_last_step" -if [ -n "$MARKER" ] && - grep -E '^\[TAURI:STEP\]' "$LOG" 2>/dev/null | grep -qE "$MARKER" && - ! printf '%s\n' "$_last_step" | grep -qE "$MARKER"; then +mismatch=false +if marked_step_over; then + mismatch=true echo "::warning::killed in '$_last_step', not the marked step -- that step was already over" fi +# Only simple values: the workflow sources this file, so the step text stays out of it. { echo "interrupt_reason=$reason" echo "interrupt_killed=$killed" echo "installer_exit=$rc" + echo "interrupt_step_mismatch=$mismatch" } > "$(dirname "$LOG")/interrupt.env" exit 0 diff --git a/.github/workflows/interrupted-install-ci.yml b/.github/workflows/interrupted-install-ci.yml index 6b0a9d87ad..a09d44ebe7 100644 --- a/.github/workflows/interrupted-install-ci.yml +++ b/.github/workflows/interrupted-install-ci.yml @@ -77,7 +77,13 @@ jobs: # The exact reported case: killed during the step that installs structlog. - {os: macos-14, label: studio-deps, marker: 'studio deps', experimental: false} # Coarse phases, earliest to latest -- each leaves a different partial venv. - - {os: macos-14, label: venv, marker: '\[TAURI:STEP\] Creating virtual environment', experimental: false} + # venv is experimental because the step is not reliably interruptible: with a + # warm uv cache creating it takes ~0.1s (staging run 30419729244 logged + # 03:31:07.371 -> 07.478 between its step line and "Installing PyTorch"), less + # than the log poll, so the kill often lands in the next step. The landing check + # now FAILS that instead of warning, and this leg must not block the PR on a race + # no log poll can win. It still probes the earliest torn state whenever it lands. + - {os: macos-14, label: venv, marker: '\[TAURI:STEP\] Creating virtual environment', experimental: true} - {os: macos-14, label: torch, marker: '\[TAURI:STEP\] Installing PyTorch', experimental: false} - {os: macos-14, label: unsloth, marker: '\[TAURI:STEP\] Installing Unsloth', experimental: false} - {os: macos-14, label: setup, marker: '\[TAURI:STEP\] Running Unsloth setup', experimental: false} @@ -143,6 +149,17 @@ jobs: tail -30 logs/install.log || true exit 1 fi + # ...and the signal has to have landed in the step this leg is named after. A + # step whose line is no longer the last one was already over when the poll saw + # it, so the kill hit the NEXT step and the leg silently duplicates another one + # while its label claims otherwise. A warning here proves nothing, so it fails. + # Sub-step markers ("studio deps") print no [TAURI:STEP] line and are exempt. + if [ "$interrupt_step_mismatch" = "true" ]; then + echo "::error::the signal landed after '${{ matrix.marker }}' finished, so this" + echo "::error::leg interrupted a later step than the one it is named for." + grep -E '^\[TAURI:STEP\]' logs/install.log || true + exit 1 + fi - name: What state is the install in? id: probe @@ -277,6 +294,15 @@ jobs: Get-Content logs/install.log -Tail 30 -ErrorAction SilentlyContinue exit 1 } + # Same landing check as the POSIX leg: a step that was already over when the poll + # saw its line means the kill hit the NEXT step, so the leg duplicates another + # one while its label claims otherwise. + if ($vals['interrupt_step_mismatch'] -eq 'true') { + Write-Host "::error::the signal landed after '${{ matrix.marker }}' finished, so this" + Write-Host '::error::leg interrupted a later step than the one it is named for.' + Select-String -Path logs/install.log -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue + exit 1 + } - name: What state is the install in? id: probe