diff --git a/.github/scripts/interrupt-install.ps1 b/.github/scripts/interrupt-install.ps1 index 05e3dc237c..f5f5eb7bc4 100644 --- a/.github/scripts/interrupt-install.ps1 +++ b/.github/scripts/interrupt-install.ps1 @@ -16,7 +16,7 @@ param( [string]$LogPath = 'logs/install.log', [string]$InstallArgs = '', [int]$KillAtSeconds = 900, - [int]$KillAfterMarkerSeconds = 3 + [int]$KillAfterMarkerSeconds = 0 ) $ErrorActionPreference = 'Continue' @@ -62,45 +62,58 @@ function Stop-Tree([int]$RootId) { catch { } } -function Get-StepCount([string]$Path) { - @(Select-String -Path $Path -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue).Count +# A leg can be aimed at either kind of phase the installer prints, and only one of them is +# a line. install.ps1 prints "[TAURI:STEP] " lines, while the dependency pass rewrites +# ONE physical line with \r (install_python_stack.py:2499), so its sub-steps are +# CR-separated SEGMENTS. Splitting on \r is what makes a sub-step's END observable at all. +$SubRe = '\[[=-]+\]\s*\d+/\d+\s' + +function Get-PhaseLines([string]$Path) { + $raw = Get-Content -Path $Path -Raw -ErrorAction SilentlyContinue + if (-not $raw) { return @() } + return @(($raw -replace "`r", "`n") -split "`n") } -function Get-LastStep([string]$Path) { - $steps = @(Select-String -Path $Path -Pattern '^\[TAURI:STEP\]' -ErrorAction SilentlyContinue) - if ($steps.Count) { return $steps[-1].Line } +function Get-LastPhase([string]$Path) { + $p = @(Get-PhaseLines $Path | Where-Object { $_ -match '^\[TAURI:STEP\]' -or $_ -match $SubRe }) + if ($p.Count) { return $p[-1] } 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 { +# True when the phase the marker named is no longer the running one. A sub-step marker is +# judged against the running sub-step, a step marker against the running step -- a step is +# not "over" because the sub-steps beneath it advanced. +function Test-MarkedPhaseOver { 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) + $lines = @(Get-PhaseLines $LogPath) + $subs = @($lines | Where-Object { $_ -match $SubRe }) + if ($subs | Where-Object { $_ -match $Marker }) { + $last = Get-LastPhase $LogPath + return -not ($last -match $SubRe -and $last -match $Marker) + } + $steps = @($lines | Where-Object { $_ -match '^\[TAURI:STEP\]' }) + if ($steps | Where-Object { $_ -match $Marker }) { + return ($steps[-1] -notmatch $Marker) + } + return $false } $killed = $false $reason = '' -# Half-second slices: a sub-second step is over before a 1s poll sees its line. -for ($i = 0; $i -lt ($KillAtSeconds * 2); $i++) { +# Fifth-of-a-second slices: every phase label prints BEFORE its work starts, so the poll +# delay is the whole distance between the label and the signal. +for ($i = 0; $i -lt ($KillAtSeconds * 5); $i++) { if ($proc.HasExited) { $reason = 'exited-before-marker'; break } if ($Marker) { $hit = Select-String -Path $LogPath -Pattern $Marker -SimpleMatch:$false -ErrorAction SilentlyContinue if ($hit) { - # Same beat as the POSIX driver, in slices and cut short once a later [TAURI:STEP] - # line appears, so a fast step does not send the signal into the step after it. - # Skipped when the step is ALREADY over: the cut-short cannot help once the next - # line is logged, and beating on would push the signal deeper into the next 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 } - } + # Same as the POSIX driver: no beat by default, because the label prints before the + # work, so killing at detection is already inside the phase while a flat beat sends + # the signal into a LATER phase. The loop stops the moment the marked phase ends. + for ($j = 0; $j -lt ($KillAfterMarkerSeconds * 5); $j++) { + if (Test-MarkedPhaseOver) { break } + Start-Sleep -Milliseconds 200 + if ($proc.HasExited) { break } } # The installer can finish inside the delay; recording marker-hit before it # let a COMPLETED install satisfy the landing assertion and probe HEALTHY. @@ -146,14 +159,14 @@ Get-Content $LogPath -Tail 15 -ErrorAction SilentlyContinue if ($Marker -and -not (Select-String -Path $LogPath -Pattern $Marker -ErrorAction SilentlyContinue)) { Write-Host "::warning::marker '$Marker' never appeared -- killed at the deadline, not the intended step" } -# Where the signal actually landed. A sub-second step can end before any poll sees its -# line, and the leg then kills the NEXT step while its label claims otherwise. Sub-step -# markers print no [TAURI:STEP] line, so the test skips them instead of always warning. -$lastStep = Get-LastStep $LogPath -Write-Host "[interrupt] step at kill: $lastStep" -$mismatch = Test-MarkedStepOver +# Where the signal actually landed. A phase that ended before the poll saw the marker sends +# the kill into a LATER phase, and the leg then duplicates whichever leg owns that phase +# while its own label claims otherwise. +$lastPhase = Get-LastPhase $LogPath +Write-Host "[interrupt] phase at kill: $lastPhase" +$mismatch = Test-MarkedPhaseOver if ($mismatch) { - Write-Host "::warning::killed in '$lastStep', not the marked step -- that step was already over" + Write-Host "::warning::killed in '$lastPhase', not the marked phase -- that phase 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. @@ -161,6 +174,6 @@ if ($mismatch) { "interrupt_reason=$reason" "interrupt_killed=$killed" "installer_exit=$rc" - "interrupt_step_mismatch=$(if ($mismatch) { 'true' } else { 'false' })" + "interrupt_phase_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 5a9b052ce5..1fd255b037 100755 --- a/.github/scripts/interrupt-install.sh +++ b/.github/scripts/interrupt-install.sh @@ -9,7 +9,8 @@ # # Usage: bash .github/scripts/interrupt-install.sh "" "" [-- install args] # log regex to wait for before killing, e.g. "studio deps"; "" kills at deadline. -# Env: KILL_AT_SECONDS deadline (default 900), KILL_GRACE grace before SIGKILL (default 10) +# Env: KILL_AT_SECONDS deadline (default 900), KILL_GRACE grace before SIGKILL (default 10), +# KILL_AFTER_MARKER_SECONDS beat between the marker and the signal (default 0) set -uo pipefail MARKER="${1:-}" @@ -39,39 +40,59 @@ 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() { +# A leg can be aimed at either kind of phase the installer prints, and only one of them is +# a line. install.sh prints "[TAURI:STEP] " lines, while the dependency pass rewrites +# ONE physical line with \r (install_python_stack.py:2499), so its ten sub-steps are +# CR-separated SEGMENTS. Splitting on \r is what makes a sub-step's END observable at all: +# without it the "studio deps" leg of staging run 30419729244 killed at "7/10 data designer +# deps" with backend_ok=true, having installed the structlog it exists to remove. +SUB_RE='\[[=-]+\][[:space:]]*[0-9]+/[0-9]+[[:space:]]' +phase_lines() { tr '\r' '\n' < "$LOG" 2>/dev/null || true; } + +# True when the phase the marker named is no longer the running one. A sub-step marker is +# judged against the running sub-step, a step marker against the running step -- a step is +# not "over" because the sub-steps beneath it advanced. A marker naming neither is not +# judged. Results go through variables, never a `| grep -q`, which can report SIGPIPE +# through pipefail on a long log. +marked_phase_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 + local lines steps subs last + lines="$(phase_lines)" + steps="$(printf '%s\n' "$lines" | grep -aE '^\[TAURI:STEP\]')" || true + subs="$(printf '%s\n' "$lines" | grep -aE "$SUB_RE")" || true + if [ -n "$subs" ] && [[ $subs =~ $MARKER ]]; then + last="$(printf '%s\n' "$lines" | grep -aE "^\[TAURI:STEP\]|$SUB_RE" | tail -1)" || true + [[ $last =~ $SUB_RE && $last =~ $MARKER ]] && return 1 + return 0 + fi + if [ -n "$steps" ] && [[ $steps =~ $MARKER ]]; then + last="$(printf '%s\n' "$steps" | tail -1)" + [[ $last =~ $MARKER ]] && return 1 + return 0 + fi + return 1 } killed=false reason="" -# Half-second slices: a sub-second step is over before a 1s poll sees its line. -for i in $(seq 1 $(( KILL_AT_SECONDS * 2 ))); do +# Fifth-of-a-second slices: every phase label prints BEFORE its work starts, so the poll +# delay is the whole distance between the label and the signal. +for i in $(seq 1 $(( KILL_AT_SECONDS * 5 ))); do if ! kill -0 "$PID" 2>/dev/null; then reason="exited-before-marker" break fi if [ -n "$MARKER" ] && grep -qE "$MARKER" "$LOG" 2>/dev/null; then - # A beat into the step so the kill lands mid-work, cut short the moment a later - # [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 and keep the whole beat. Skipped when the step is - # ALREADY over: the cut-short cannot help once the next line is logged and beating on - # only pushes the signal deeper, so kill now and let the mismatch check below report. - 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 + # No beat by default: the label prints before the work, so killing at detection is + # already inside the phase, while a flat 3s beat is what pushed 5 of the 12 legs in + # staging run 30419729244 into a LATER phase (venv -> torch produced a byte-identical + # log to the torch leg). Legs whose phase runs for minutes pass a beat explicitly to + # land mid-work; the loop still stops the moment the marked phase ends. + for _ in $(seq 1 $(( ${KILL_AFTER_MARKER_SECONDS:-0} * 5 ))); do + marked_phase_over && break + sleep 0.2 + kill -0 "$PID" 2>/dev/null || break + done # ...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 @@ -82,7 +103,7 @@ for i in $(seq 1 $(( KILL_AT_SECONDS * 2 ))); do killed=true break fi - sleep 0.5 + sleep 0.2 done if [ "$killed" != "true" ] && kill -0 "$PID" 2>/dev/null; then @@ -127,21 +148,21 @@ tail -15 "$LOG" || true if [ -n "$MARKER" ] && ! grep -qE "$MARKER" "$LOG" 2>/dev/null; then echo "::warning::marker '$MARKER' never appeared -- this leg killed at the deadline, not at the intended step" fi -# Where the signal actually landed. A sub-second step can end before any poll sees its -# line, and the leg then kills the NEXT step while its label claims otherwise. Sub-step -# 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" +# Where the signal actually landed. A phase that ended before the poll saw the marker sends +# the kill into a LATER phase, and the leg then duplicates whichever leg owns that phase +# while its own label claims otherwise. +_last_phase="$(phase_lines | grep -aE "^\[TAURI:STEP\]|$SUB_RE" | tail -1)" || true +echo "[interrupt] phase at kill: $_last_phase" mismatch=false -if marked_step_over; then +if marked_phase_over; then mismatch=true - echo "::warning::killed in '$_last_step', not the marked step -- that step was already over" + echo "::warning::killed in '$_last_phase', not the marked phase -- that phase was already over" fi -# Only simple values: the workflow sources this file, so the step text stays out of it. +# Only simple values: the workflow sources this file, so the phase text stays out of it. { echo "interrupt_reason=$reason" echo "interrupt_killed=$killed" echo "installer_exit=$rc" - echo "interrupt_step_mismatch=$mismatch" + echo "interrupt_phase_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 50bfc75ddf..4567c13b22 100644 --- a/.github/workflows/interrupted-install-ci.yml +++ b/.github/workflows/interrupted-install-ci.yml @@ -70,26 +70,35 @@ jobs: fail-fast: false matrix: include: - # The exact reported case: killed during the step that installs structlog. - - {os: macos-14, label: studio-deps, marker: 'studio deps', experimental: false} + # `beat` is the delay between the marker and the signal, in seconds. It is 0 + # everywhere except the three steps that provably run for minutes: every phase + # label prints BEFORE its work starts, so killing at detection is already inside + # the phase, while any beat longer than the phase lands the signal in the NEXT + # one. A flat 3s beat is what made 5 of the 12 legs of staging run 30419729244 + # interrupt a later phase than their label claims. + # + # The exact reported case: killed during the sub-step that installs structlog. + - {os: macos-14, label: studio-deps, marker: 'studio deps', beat: 0, experimental: false} # Coarse phases, earliest to latest -- each leaves a different partial venv. - # venv is experimental: with a warm uv cache the step takes ~0.1s (staging run - # 30419729244 logged 03:31:07.371 -> 07.478 between its step line and "Installing - # PyTorch"), under the log poll, so the kill often lands in the next step and the - # landing check FAILS it. It still probes the earliest torn state when 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} - # Other dependency-pass steps around the named one. - - {os: macos-14, label: pip-bootstrap, marker: 'pip bootstrap', experimental: false} + # venv is experimental: the step takes ~0.1s (30419729244 logged 03:31:07.371 -> + # 07.478 between its line and "Installing PyTorch"), shorter than any log poll, so + # the kill usually lands in the next phase and the landing check FAILS it. It + # still probes the earliest torn state when it does land. + - {os: macos-14, label: venv, marker: '\[TAURI:STEP\] Creating virtual environment', beat: 0, experimental: true} + - {os: macos-14, label: torch, marker: '\[TAURI:STEP\] Installing PyTorch', beat: 3, experimental: false} + - {os: macos-14, label: unsloth, marker: '\[TAURI:STEP\] Installing Unsloth', beat: 3, experimental: false} + - {os: macos-14, label: setup, marker: '\[TAURI:STEP\] Running Unsloth setup', beat: 3, experimental: false} + # Other dependency-pass sub-steps around the named one. pip-bootstrap is + # experimental for the same reason as venv: in 30419729244 it landed in "2/10 + # unsloth extras", producing a log byte-identical to the unsloth-extras leg. + - {os: macos-14, label: pip-bootstrap, marker: 'pip bootstrap', beat: 0, experimental: true} # No base-packages cell: --local sets skip_base, so install_python_stack returns # before "base packages" ever prints -- that leg ran to completion, proving nothing. - - {os: macos-14, label: unsloth-extras, marker: 'unsloth extras', experimental: true} - - {os: macos-14, label: data-designer, marker: 'data designer deps', experimental: true} + - {os: macos-14, label: unsloth-extras, marker: 'unsloth extras', beat: 0, experimental: true} + - {os: macos-14, label: data-designer, marker: 'data designer deps', beat: 0, experimental: true} # Linux: same teardown path, different package manager and process semantics. - - {os: ubuntu-latest, label: studio-deps, marker: 'studio deps', experimental: false} - - {os: ubuntu-latest, label: torch, marker: '\[TAURI:STEP\] Installing PyTorch', experimental: false} + - {os: ubuntu-latest, label: studio-deps, marker: 'studio deps', beat: 0, experimental: false} + - {os: ubuntu-latest, label: torch, marker: '\[TAURI:STEP\] Installing PyTorch', beat: 3, experimental: false} steps: - uses: actions/checkout@de0fac2e4500dabe0009e67214ff5f5447ce83dd # v6.0.2 @@ -106,6 +115,7 @@ jobs: env: GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} KILL_AT_SECONDS: '1500' + KILL_AFTER_MARKER_SECONDS: '${{ matrix.beat }}' run: | # --local is load-bearing. Without it install.sh:3996 resolves # `unsloth>=2026.7.5` from PyPI, so the venv gets the PUBLISHED CLI, every @@ -139,14 +149,15 @@ jobs: tail -30 logs/install.log || true exit 1 fi - # ...and the signal must land in the step this leg is named after. A step whose - # line is no longer the last was already over when the poll saw it, so the kill - # hit the NEXT step and the leg duplicates another one under a false label. - # 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 + # ...and the signal must land in the phase this leg is NAMED for. Warning-only + # left staging run 30419729244 fully green with the venv leg's install.log + # byte-identical to the torch leg's, and both "studio deps" legs killed past + # structlog (their own probe artefacts report backend_ok=true), so the flagship + # cell never reproduced the bug it is named after. + if [ "$interrupt_phase_mismatch" = "true" ]; then + echo "::error::the kill landed in a LATER phase than '${{ matrix.marker }}', so this" + echo "::error::leg duplicates whichever leg owns that phase and its label lies." + tr '\r' '\n' < logs/install.log | grep -aE '^\[TAURI:STEP\]|\[[=-]+\] *[0-9]+/[0-9]+' || true exit 1 fi @@ -233,8 +244,9 @@ jobs: include: # install.ps1:121 parses `--no-torch`; `-SkipTorch` matches no case there and is # silently dropped. The torch leg must NOT skip torch or its marker never appears. - - {label: studio-deps, marker: 'studio deps', installArgs: '--tauri --no-torch --local'} - - {label: torch, marker: 'Installing PyTorch', installArgs: '--tauri --local'} + # `beat` as in the POSIX job: 0 for the sub-step, 3 for the minutes-long torch step. + - {label: studio-deps, marker: 'studio deps', beat: 0, installArgs: '--tauri --no-torch --local'} + - {label: torch, marker: 'Installing PyTorch', beat: 3, installArgs: '--tauri --local'} steps: - uses: actions/checkout@de0fac2e4500dabe0009e67214ff5f5447ce83dd # v6.0.2 @@ -246,7 +258,8 @@ jobs: run: | pwsh -NoProfile -File .github/scripts/interrupt-install.ps1 ` -Marker '${{ matrix.marker }}' -LogPath logs/install.log ` - -InstallArgs '${{ matrix.installArgs }}' -KillAtSeconds 1500 + -InstallArgs '${{ matrix.installArgs }}' -KillAtSeconds 1500 ` + -KillAfterMarkerSeconds ${{ matrix.beat }} - name: The kill must have landed where it was aimed shell: pwsh @@ -274,12 +287,13 @@ jobs: Get-Content logs/install.log -Tail 30 -ErrorAction SilentlyContinue exit 1 } - # Same landing check as the POSIX leg: a step already over when the poll saw its - # line means the kill hit the NEXT step, so the leg duplicates another one. - 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 + # Same landing check as the POSIX leg: a phase already over when the poll saw the + # marker means the kill hit a LATER phase, so the leg duplicates another one. + if ($vals['interrupt_phase_mismatch'] -eq 'true') { + Write-Host "::error::the kill landed in a LATER phase than '${{ matrix.marker }}', so this" + Write-Host '::error::leg duplicates whichever leg owns that phase and its label lies.' + ((Get-Content logs/install.log -Raw) -replace "`r", "`n") -split "`n" | + Where-Object { $_ -match '^\[TAURI:STEP\]' -or $_ -match '\[[=-]+\]\s*\d+/\d+\s' } exit 1 }