pregate: remote heartbeat sanitizes and tolerates a removed log; timeout detail names its source (review fixes)

Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com>

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.

lib/pregate/supervise.ts

@@ -186,7 +186,11 @@ export function supervise(o: SuperviseOptions): Promise<Supervised> {
       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);

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

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);
 

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');
   });
 });