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