diff --git a/lib/pregate/checks/lanes.ts b/lib/pregate/checks/lanes.ts index bbe90e694..f1206404c 100644 --- a/lib/pregate/checks/lanes.ts +++ b/lib/pregate/checks/lanes.ts @@ -428,7 +428,8 @@ async function runRemote(ctx: PregateContext, sel: Selection, base: CheckResult) ctx.progress(`PREGATE_REMOTE_SPEND: ${spend.slice('spend: '.length)}`); const runLines = [...lines, `remote gate: ${obligation.command}`, `log: ${log}`, spend, ...output.trim().split('\n').slice(-15).map(l => ` ${l}`)]; const inputs = { ...base.inputs, command: sha256(obligation.command!) }; - const why = r.outcome !== 'exited' ? `the remote gate did not finish (${r.outcome})` + const why = r.outcome === 'timeout' ? `the remote gate did not finish (timed out after ${ctx.timeoutMs / 1000} s, ${ctx.timeoutSource})` + : r.outcome !== 'exited' ? `the remote gate did not finish (${r.outcome})` : !reported ? `the remote gate exited ${r.exit} without a PREGATE_REMOTE: line` : remoteReportProblem(reported, ctx.wtree) ?? (r.exit !== 0 ? `the remote gate exited ${r.exit}` : null); // A gate that printed no report and names a quota, network or missing-tool error in its preamble never ran the tests: the environment, not the diff. diff --git a/lib/pregate/supervise.ts b/lib/pregate/supervise.ts index fc0af0811..a7ff3ed88 100644 --- a/lib/pregate/supervise.ts +++ b/lib/pregate/supervise.ts @@ -186,7 +186,11 @@ export function supervise(o: SuperviseOptions): Promise { if (now >= o.deadline) { stop('timeout'); return; } if (o.stallMs > 0 && now - lastGrowth >= o.stallMs) { stop('stalled'); return; } if (now - lastProgress < heartbeatMs) return; - const last = o.lastLine ? readRange(o.log, start, size, 4096).split('\n').map(l => l.trim()).filter(Boolean).at(-1) : undefined; + let last: string | undefined; + if (o.lastLine) { + try { last = readRange(o.log, start, size, 4096).replace(/\x1b\[[0-9;?]*[A-Za-z]/g, '').split(/\r\n?|\n/).map(l => l.replace(/[\x00-\x1f\x7f]/g, '').trim()).filter(Boolean).at(-1); } + catch { /* log removed */ } + } emit(`PREGATE_HEARTBEAT: ${o.label} running ${Math.round((now - started) / 1000)}s; last file ${lastFile ?? 'none reported'}; log ${size - start} bytes, last growth ${Math.round((now - lastGrowth) / 1000)}s ago (${o.log})${last ? `; last output: ${last.slice(0, 160)}` : ''}`); }, pollMs); if (child.pid) ACTIVE.add(child.pid); diff --git a/scripts/ubicloud/pregate-remote.sh b/scripts/ubicloud/pregate-remote.sh index 0759ee9b1..68e5b5692 100755 --- a/scripts/ubicloud/pregate-remote.sh +++ b/scripts/ubicloud/pregate-remote.sh @@ -185,7 +185,7 @@ args=(run -s "$size" --src "$root" --setup "$prelude" [ -z "${GSTACK_FREE_JOBS:-}" ] || args+=(--env "GSTACK_FREE_JOBS=$GSTACK_FREE_JOBS") # The VM run gets its own session (python3, which ubi-runner already needs, for -# setsid on Linux and macOS): pregate's --timeout and stall kill signal this +# setsid on Linux and macOS): pregate's --timeout kill signals this # script's process group and then SIGKILL it, which must never cut ubi-runner's # teardown short. Output goes to files (a dead reader would SIGPIPE ubi-runner), # stamped for the phase timings; this script streams it. A watchdog sends diff --git a/test/pregate-remote.test.ts b/test/pregate-remote.test.ts index f6740bb83..ca781b02e 100644 --- a/test/pregate-remote.test.ts +++ b/test/pregate-remote.test.ts @@ -200,7 +200,7 @@ describe('gstack-pregate --remote (C-c)', () => { const late = remote(repo, ['--remote', '--allow-repo-commands', '--spend-cap', '2', '--timeout', '2'], { GATE_QUIET_MS: '8000' }); expect(late.status).toBe(EXIT.fail); expect(lanes(repo)).toMatchObject({ status: 'incomplete', code: 'PREGATE_INCOMPLETE' }); - expect(lanes(repo).detail).toContain('the remote gate did not finish (timeout)'); + expect(lanes(repo).detail).toContain('the remote gate did not finish (timed out after 2 s, --timeout)'); expect(pregateFile(repo).requires_remote[0].receipt).toBeNull(); }, 60_000); diff --git a/test/pregate-supervise.test.ts b/test/pregate-supervise.test.ts index 0ba8a5d7b..70921184a 100644 --- a/test/pregate-supervise.test.ts +++ b/test/pregate-supervise.test.ts @@ -99,6 +99,19 @@ describe('supervise: process group, log file, stall and deadline', () => { const r = await run(dir, 'echo "waiting on run 7 (in_progress)"; sleep 1.2; echo done', { heartbeatMs: 300, lastLine: true }); expect(r.outcome).toBe('exited'); expect(r.lines.some(l => l.startsWith('PREGATE_HEARTBEAT: fixture running ') && l.includes('last output: waiting on run 7 (in_progress)'))).toBe(true); + const redraw = await run(dir, "printf 'run 7 queued\\r\\033[2Krun 7 in_progress\\n'; sleep 1.2", { heartbeatMs: 300, lastLine: true }); + expect(redraw.lines.some(l => l.endsWith('last output: run 7 in_progress'))).toBe(true); + expect(redraw.lines.some(l => l.includes('\x1b') || l.includes('\r'))).toBe(false); + }); + + // Value: protects=reading the last line is best effort: a log that disappears mid-run never throws out of the supervisor's timer, which would + // abandon the gate's deadline and cleanup (GST-431 review); fails_when=lastLine sampling throws ENOENT; why_new=lastLine is new; seam=none; no_claim=none + test('with lastLine, a log removed mid-run still ends in a normal outcome', async () => { + const dir = scratch(); + const log = path.join(dir, 'run.log'); + fs.writeFileSync(log, ''); + const r = await supervise({ command: `echo hi; sleep 0.4; rm -f "${log}"; sleep 1.2; echo done`, cwd: dir, env: process.env, log, deadline: Date.now() + 30_000, stallMs: 0, graceMs: 300, pollMs: 50, heartbeatMs: 300, lastLine: true, label: 'fixture', progress: () => {} }); + expect(r.outcome).toBe('exited'); }); });