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 :⚠️:.
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.
This commit is contained in:
Daniel Han
parent
055100bff4
commit
1892b130ce
3 changed files with 86 additions and 19 deletions
41
.github/scripts/interrupt-install.ps1
vendored
41
.github/scripts/interrupt-install.ps1
vendored
|
|
@ -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
|
||||
|
|
|
|||
36
.github/scripts/interrupt-install.sh
vendored
36
.github/scripts/interrupt-install.sh
vendored
|
|
@ -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
|
||||
|
|
|
|||
28
.github/workflows/interrupted-install-ci.yml
vendored
28
.github/workflows/interrupted-install-ci.yml
vendored
|
|
@ -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
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue