From e7f0669b04e2242548c3e55acd0ccc3bb62a7c8f Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 17:53:28 -0400 Subject: [PATCH 01/13] feat: cap background job log output, and make readers honest about it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The write side of a job log was unbounded: stdout+stderr went straight to the log fd, so a runaway job (`yes`, a spew loop, a pathological build) could fill the disk. The read side was already bounded, so the fix is a ceiling enforced INSIDE the detached process tree — it has to hold after pi exits or crashes. Wrapper (extension/index.ts): the command's output is tee'd into a byte counter and piped through `head -c CAP` into the log, with `cat >/dev/null` draining the rest, so the producer never gets SIGPIPE and the job still exits with its real code (the code travels through a file — a pipeline's `$?` is the reader's). The count comes from the tee'd copy, not from "what head left behind": head over-reads into its buffer, so the remainder under-reports (a 1500-byte stream capped at 1000 leaves 0, not 500), and the log fd cannot be re-opened for sizing (it is O_WRONLY). If mkfifo fails the wrapper falls back to uncapped — losing output is worse than losing the ceiling. - `maxLogBytes` / `PI_BGRUN_MAX_LOG_BYTES`, default 64 MiB, 0 = unlimited (a blank env var does NOT mean unlimited). Read per job at spawn time. - The cap keeps the FIRST N bytes; there is no portable in-tree tail cap, and a ring buffer would break the marker-at-tail contract every reader relies on. - Truncation is never silent: the log gets `[pi-bgrun] output truncated at N bytes (first N bytes kept)` on the line before the exit marker, and readers filter it like the exit marker. The wake's Stats line says so, a configured digest scorecard is SKIPPED rather than scored against a log that lost its end (summaries and failure lists live there), and bgtail/bggrep append a note and report truncatedAtBytes in their details. - bgtail/bggrep take `bytes` (2 MiB default, max 64 MiB). Widening only changes how much is SCANNED — the returned text stays capped by the condenser, so a wider window costs latency and memory, not context. A changed window resets bgtail's delta instead of reporting never-seen lines as new. - countLogLines is bounded (64 MiB, else the stat is omitted) and takes its tail offset from fstatSync; the sweep reclaims `.tmp-*.{log,ec,fifo,cnt}` staging files; tailBookmarks is evicted when a log is removed and capped at 1000. Tests: 18 new, covering the cap boundary (exact-cap is not "truncated"), exit-code preservation through the pipeline, a multi-megabyte flood not dying of SIGPIPE, no staging strays, digest/stat/last-line honesty, the `bytes` window, and config normalization. --- README.md | 67 +++- extension/index.test.ts | 668 +++++++++++++++++++++++++++++++++++++++- extension/index.ts | 438 ++++++++++++++++++++++---- skill/run-bg/SKILL.md | 51 ++- 4 files changed, 1138 insertions(+), 86 deletions(-) diff --git a/README.md b/README.md index e3d4560..fd39a4c 100644 --- a/README.md +++ b/README.md @@ -35,8 +35,8 @@ Restart pi after install so the extension loads. | ------ | --------- | | `bgrun` | Launch a command detached in the background. Optional `name` gives the job a short human-readable label. Returns `started: ` immediately. Wakes the session automatically on completion. | | `bgstatus` | Show job status. With an id: any job's state + exit code. Without: this session's running jobs (finished jobs hidden by default — pass `includeDone: true` or set `showCompletedJobs`). Other sessions' *running* jobs are listed only when `adoptForeignJobs` is enabled; finished foreign logs from the shared dir can also appear when finished jobs are included. | -| `bgtail` | Read the newest lines of a job's log (default 40; it reads the log's **last 2 MB**), **condensed for context**: ANSI escapes stripped, repeated lines collapsed, long lines and total size capped. First read = full last-N tail; repeat reads return **only lines appended since your last read** (delta tailing) — polling a running job never re-pays for lines already seen. Pass `raw: true` for the unprocessed last-N window (still advances the bookmark). | -| `bggrep` | Regex search over the **last 2 MB** of a job's log: line-numbered matches, optional `context` lines, each line pre-truncated to 10 000 chars before matching, results capped (~50 matches, ~8KB) and condensed. Runs inside the extension, so it reaches the configured jobs dir (including a global one) that project-sandboxed tools (`ctx_execute_file`) cannot. Matching runs under a wall-clock budget ([Bounded matching](#bounded-matching)). With no `pattern`, a generic failure-signature default is used (override it — convenience, not guarantee). | +| `bgtail` | Read the newest lines of a job's log (default 40; it reads the log's **last 2 MB** — widen with `bytes`, max 64 MiB), **condensed for context**: ANSI escapes stripped, repeated lines collapsed, long lines and total size capped. First read = full last-N tail; repeat reads return **only lines appended since your last read** (delta tailing) — polling a running job never re-pays for lines already seen. Pass `raw: true` for the unprocessed last-N window (still advances the bookmark). | +| `bggrep` | Regex search over the **last 2 MB** of a job's log (`bytes` widens the window, max 64 MiB): line-numbered matches, optional `context` lines, each line pre-truncated to 10 000 chars before matching, results capped (~50 matches, ~8KB) and condensed. Resolves the job id to the configured jobs dir itself — no log path to reconstruct. `ctx_execute_file` can read the same file (it takes an absolute path; only your Read-deny rules apply), but it needs that path. Matching runs under a wall-clock budget ([Bounded matching](#bounded-matching)). With no `pattern`, a generic failure-signature default is used (override it — convenience, not guarantee). | | `bgclean` | Remove old job logs. **Default scope: this session's jobs only** — other sessions' logs are untouched — and it also drops stale per-project digest markers (`.bgrun-used-*`, `.digest-nudge-*`) in the session's jobs dir (markers are not session data). Pass `all: true` to sweep every shared jobs dir — under the project-local default that is the project's dir plus the machine-global one, while an explicit absolute `jobsDir` is swept alone — and do the same marker sweep across them. Retention: `cleanupDays` config (7 days); `days` must be a positive number (`days: 0` is rejected rather than purging everything). Never removes a running job's log. | ## Slash commands @@ -85,8 +85,9 @@ exit code even after a restart. ## Reading results without flooding context -Two-tier read model — the log file stays complete on disk for deep analysis; -only bounded digests ever enter the conversation: +Two-tier read model — the log file itself stays on disk, capped (see +[log size ceiling](#log-size-ceiling)), for deep analysis; only bounded digests +ever enter the conversation: - **Quick peek:** `bgtail ` — condensed newest lines (ANSI stripped, repeats collapsed, ~2KB/line and ~8KB caps). The first read is the last-40-lines tail; each later @@ -94,21 +95,29 @@ only bounded digests ever enter the conversation: free. The wake message itself already carries the exit code and the log's last line, so many turns need no follow-up read at all. - **Pattern search:** `bggrep [pattern] [context]` — line-numbered matches, - capped and condensed (~50 matches, ~2KB/line, ~8KB); works on global jobs dirs that `ctx_execute_file` - cannot reach. Pass your own pattern when you know the log's format. + capped and condensed (~50 matches, ~2KB/line, ~8KB); takes the job id, so + there is no log path to reconstruct. Searches the **last 2 MB** by default — + pass `bytes` to widen (max 64 MiB), or use `ctx_execute_file` on the path for + whole-file code-based analysis. Pass your own pattern when you know the log's + format. A **wider window costs latency and memory, not context**: the returned + matches stay capped either way. - **Whole-log analysis:** `ctx_execute_file` on the job's log path (reachable when logs are project-local) to extract only failure lines. Never `cat` or - `Read` a full bgrun log. + `Read` a full bgrun log. The sandbox keeps the file's bytes out of context — + only your script's **stdout** enters it — so print aggregates and capped + slices (`fails.slice(0, 40)`), never the content. With a 64 MiB-ceiling log, + an unsliced `console.log(FILE_CONTENT)` is the one way this path becomes the + dump it exists to avoid; use `bgtail`/`bggrep` first, and this third. **Why `bggrep` instead of `bash grep` on the log?** A bash grep's output is uncapped — a retry-storm log can dump thousands of matching lines straight into context, and safety depends on remembering `| head` on every call. -`bggrep` is bounded by design (last 2 MB of the log, per-line 10 000-char -pre-truncation before matching, ~50 matches, ~8KB), takes the job id instead of -a reconstructed log path (no shell-quoting of the regex), reaches the -configured jobs dir (including a global one) that project-sandboxed tools like -`ctx_execute_file` cannot, and reports match counts, line numbers, and -skip markers. Plain `grep` is fine only for a one-off search you know is tiny. +`bggrep` is bounded by design (last 2 MB of the log by default — `bytes` widens +it, max 64 MiB — per-line 10 000-char pre-truncation before matching, ~50 +matches, ~8KB), takes the job id instead of +a reconstructed log path (no shell-quoting of the regex), resolves the job id to the +configured jobs dir itself (no path to reconstruct), and reports match counts, +line numbers, and skip markers. Plain `grep` is fine only for a one-off search you know is tiny. ### Bounded matching @@ -121,6 +130,36 @@ and `bggrep` returns an error — **a runaway pattern fails, it never hangs the session.** Normal patterns and logs finish far inside the budget; worker startup adds a few tens of milliseconds per call. +### Log size ceiling + +stdout+stderr used to go straight to the log file with no write bound, so a +runaway job (`yes`, a spew loop, a pathological build) could fill the disk and +take the machine down. Job logs are now capped (`maxLogBytes` / `PI_BGRUN_MAX_LOG_BYTES`, +default **64 MiB**, `0` = unlimited): + +- The cap keeps the **first** N bytes. There is no portable in-tree way to keep + the tail — a ring buffer needs a helper binary, and rewriting the file breaks + the readers that depend on the exit marker staying last. A job past 64 MiB is + almost always a runaway, so the head is the useful part. +- The ceiling lives **inside the detached process tree**, so it still holds + after pi exits or crashes — it is not a pi-side watchdog. +- The job is **not** killed, and its real exit code is preserved: bytes past the + cap are drained and discarded instead of SIGPIPE'ing the producer into `141`. +- It is **not silent**. The log carries + `[pi-bgrun] output truncated at bytes (first bytes kept)` on the line + before the exit marker — filtered out of content readers exactly like the exit + marker — and every surface the agent reads is labelled instead: the wake's + Stats line gains `log truncated at 64 MiB`, `bgtail` and `bggrep` append a + note and report `truncatedAtBytes` in their details, and a configured digest + scorecard is **skipped** rather than run against a log that lost its end — + summaries and failure lists live at the end, so its numbers would be + confidently wrong. Treat a skipped digest on a capped job as "unknown", not + "no failures". +- Cost: a capped job runs through a few extra processes (`tee`, `head`, `wc`) — + a few tens of milliseconds of job startup, no steady-state overhead. +- Configure `maxLogBytes: 0` for the previous uncapped behavior, e.g. when the + whole log must survive for `ctx_execute_file`. + ## Configuration The jobs dir defaults to `/.pi-bgrun/jobs` when the session cwd is @@ -150,6 +189,7 @@ config file (trusted projects only) ← environment variables**. "adoptForeignJobs": false, "showCompletedJobs": false, "cleanupDays": 7, + "maxLogBytes": 67108864, "globalAutoClean": true, "jobsDir": "/some/other/dir" } @@ -213,6 +253,7 @@ Environment variables (same knobs, handy for one-off overrides): | `PI_BGRUN_FOREIGN_JOBS` | `false` | Adopt other sessions' running jobs into this session's widget and job list. Adopted jobs are polled so they leave the widget when they finish. | | `PI_BGRUN_SHOW_COMPLETED` | `false` | Include finished jobs in `bgstatus` listings by default. | | `PI_BGRUN_CLEANUP_DAYS` | `7` | Log retention for cleanup sweeps and the `bgclean` default. | +| `PI_BGRUN_MAX_LOG_BYTES` | `67108864` (64 MiB) | Byte ceiling for a job's log (stdout+stderr). `0` disables it (unlimited). See [Log size ceiling](#log-size-ceiling). | | `PI_BGRUN_GLOBAL_AUTO_CLEAN` | `true` | Set `0`/`false` to disable the automatic orphan sweep (see below). | | `PI_BGRUN_GREP_TIMEOUT_MS` | `2000` | Wall-clock budget for a `bggrep` match. A caller-supplied regex that exceeds it is aborted (its worker terminated) and reported as an error instead of hanging — see [Bounded matching](#bounded-matching). | | `PI_BGRUN_USER_CONFIG` | `~/.pi/agent/pi-bgrun.json` | Override the user-level config file path (see [Configuration](#configuration)). | diff --git a/extension/index.test.ts b/extension/index.test.ts index cae199d..bd31a72 100644 --- a/extension/index.test.ts +++ b/extension/index.test.ts @@ -3518,9 +3518,11 @@ test("wake message: Stats line (duration + line count) sits between Command: and ); await waitForWakes(wakes, 1); const wake = wakes[0].text; - // Duration (0.0s for an instant job) + the command's OWN line count — the - // appended exit marker and its blank separator are excluded. - assert.match(wake, /Stats: 0\.0s, 1 lines/); + // Stats carries the command's OWN line count — the appended exit marker, + // its blank separator and (when capped) the truncation notice are excluded. + // The duration is asserted by SHAPE only: it depends on machine speed and on + // how many processes the wrapper spawns, so pinning "0.0s" pins the host. + assert.match(wake, /Stats: \d+\.\d+s, 1 lines/); const cmdIdx = wake.indexOf("Command: "); const statsIdx = wake.indexOf("Stats: "); const lastIdx = wake.indexOf("Last output: "); @@ -6029,3 +6031,663 @@ test("bgclean all: a TERMINAL exit marker reclaims a finished log despite a reus rmSync(dir, { recursive: true, force: true }); } }); + +// ── log size ceiling (maxLogBytes) ───────────────────────────────────────── +// +// A job that writes well past the caps used below: 200 numbered lines +// (~6.6 KB) plus a non-zero exit code, so the marker and the exit code are +// exercised through the capped pipeline too. + +const SPEW_LINES = + 'i=0; while [ $i -lt 200 ]; do echo "line-$i-aaaaaaaaaaaaaaaaaaaaaa"; i=$((i+1)); done; exit 3'; + +function startedId(res: { content: { text: string }[] }): string { + return (res.content[0].text as string).match(/^started: ([^\n]+)/)![1]; +} + +test("bgrun: maxLogBytes keeps the first N bytes, notes the truncation, preserves the exit code", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-sn", + { command: SPEW_LINES, name: "spew" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + // The wrapped log fd is written by ONE writer at a time, so the notice + // starts exactly at the cap: 1000 bytes of command output, then "\n". + const noticeAt = log.indexOf( + "\n[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n", + ); + assert.equal(noticeAt, 1000, "notice follows exactly the capped bytes"); + assert.ok(log.startsWith("line-0-"), "the first bytes are kept"); + assert.ok(!log.includes("line-199-"), "output past the cap was dropped"); + // Marker still last, and the real exit code survived the pipeline. + const nonBlank = log.split("\n").filter((l) => l.trim().length > 0); + assert.equal(nonBlank[nonBlank.length - 1], "__BGRUN_EXIT__=3"); + assert.match(wakes[0].text, /finished \(exit 3\)/); + }); + }); +}); + +test("bgrun: the truncation notice is not job output — not counted, not the last line", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-stats", + { command: SPEW_LINES, name: "spew" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + // Lines the caller can still READ: the capped region. Counting from the + // file (not from the implementation) keeps this honest — a trailing + // partial line is a line, exactly as the counter treats it. + const regionLines = log.slice(0, 1000).split("\n").length; + assert.match(wakes[0].text, new RegExp(`, ${regionLines} lines`)); + assert.match(wakes[0].text, /Last output: line-\d+-a+$/m); + assert.ok( + !wakes[0].text.includes("Last output: [pi-bgrun]"), + "the notice is never reported as the job's last line", + ); + }); + }); +}); + +test("bgrun: a job that outruns the cap by megabytes still finishes with its own exit code", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + // ~1.3 MB, far more than the pipe buffers between producer and reader — + // the drain must keep the producer alive (no SIGPIPE/141) and the job's + // own exit code must survive the pipeline. + const res = await tools.get("bgrun")!.execute( + "call-cap-flood", + { command: "seq 1 200000; exit 0", name: "flood" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + assert.equal(log.indexOf("\n[pi-bgrun] output truncated"), 1000); + assert.match(log, /__BGRUN_EXIT__=0\n$/); + assert.match(wakes[0].text, /finished \(exit 0\)/); + }); + }); +}); + +test("bgrun: a log at exactly the cap is not called truncated; one byte over is", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "4", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const run = async (command: string) => { + const res = await tools.get("bgrun")!.execute( + command, + { command }, + undefined, + undefined, + ctx, + ); + return startedId(res); + }; + + // "abc\n" is exactly 4 bytes — nothing was dropped. + const atCap = await run("printf 'abc\\n'"); + // "abcd\n" is 5 — the trailing newline is the byte that had to go. + const overCap = await run("printf 'abcd\\n'"); + await waitForWakes(wakes, 2); + + const exact = readFileSync(join(dir, `${atCap}.log`), "utf8"); + assert.equal(exact, "abc\n\n__BGRUN_EXIT__=0\n"); + assert.ok(!exact.includes("truncated"), "no notice at the boundary"); + + const over = readFileSync(join(dir, `${overCap}.log`), "utf8"); + assert.ok( + over.includes( + "\n[pi-bgrun] output truncated at 4 bytes (first 4 bytes kept)\n", + ), + "one byte past the cap is truncated", + ); + assert.ok(over.startsWith("abcd"), "kept the first 4 bytes"); + }); + }); +}); + +test("bgrun: maxLogBytes 0 leaves the log uncapped", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "0", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-off", + { command: SPEW_LINES, name: "spew" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + assert.ok(log.includes("line-199-"), "the whole output is kept"); + assert.ok(!log.includes("truncated"), "no notice when uncapped"); + assert.match(log, /__BGRUN_EXIT__=3\n$/); + }); + }); +}); + +test("bgrun: a capped job leaves no staging files behind", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + await tools.get("bgrun")!.execute( + "call-cap-staging", + { command: SPEW_LINES, name: "spew" }, + undefined, + undefined, + ctx, + ); + await waitForWakes(wakes, 1); + + // The exit-code file, the count fifo and the count file are the + // wrapper's own scratch — it removes them before printing the marker, so + // a wake never leaves a `.tmp-*` in the jobs dir. + const strays = readdirSync(dir).filter((n) => n.startsWith(".tmp-")); + assert.deepEqual(strays, []); + }); + }); +}); + +test("bgclean: stale staging files (.ec/.fifo/.cnt) are reclaimed, unrelated .tmp-* are not", async () => { + const dir = mkdtempSync(join(tmpdir(), "pi-bgrun-test-")); + process.env.PI_BGRUN_DIR = dir; + try { + const h = makeFakePi(); + await loadExtension(h.pi); + const stale = Date.now() - 30 * 24 * 60 * 60 * 1000; + const ours = [ + ".tmp-spew-1-abcd.ec", + ".tmp-spew-1-abcd.fifo", + ".tmp-spew-1-abcd.cnt", + ".tmp-spew-1-abcd.log", + ]; + const foreign = ".tmp-someone-else.txt"; + for (const name of [foreign, ...ours]) { + writeFileSync(join(dir, name), ""); + utimesSync(join(dir, name), new Date(stale), new Date(stale)); + } + + await h.tools + .get("bgclean")! + .execute("call-cap-sweep", { days: 7, all: true }, undefined, undefined, h.ctx); + + for (const name of ours) { + assert.ok(!existsSync(join(dir, name)), `${name} reclaimed`); + } + assert.ok(existsSync(join(dir, foreign)), "an unrelated .tmp-* is left alone"); + } finally { + delete process.env.PI_BGRUN_DIR; + rmSync(dir, { recursive: true, force: true }); + } +}); + +test("bgtail/bggrep work on a capped log and only see what was kept", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const bgtail = tools.get("bgtail")!; + const bggrep = tools.get("bggrep")!; + + // "seq 1 400" fills the 1000-byte window exactly through line 277. + const res = await bgrun.execute( + "call-cap-read", + { command: "seq 1 400", name: "seq" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const grep1 = await bggrep.execute( + "call-cap-read", + { id, pattern: "^1$" }, + undefined, + undefined, + ctx, + ); + assert.match(grep1.content[0].text as string, /L1: 1/); + + const grep400 = await bggrep.execute( + "call-cap-read", + { id, pattern: "^400$" }, + undefined, + undefined, + ctx, + ); + assert.ok( + !/L\d+: 400/.test(grep400.content[0].text as string), + "output past the cap is not searchable — it was never written", + ); + + const tail = await bgtail.execute( + "call-cap-read", + { id, lines: 3 }, + undefined, + undefined, + ctx, + ); + const tailText = tail.content[0].text as string; + // The last 3 lines of what was KEPT (277 is the cap boundary), followed + // by the truncation label — the wrapper's raw notice line stays filtered. + assert.match( + tailText, + /275\n276\n277\n\n\(log truncated at 1000 bytes/, + ); + assert.ok( + !tailText.includes("[pi-bgrun] output truncated"), + "the raw notice line is not shown as content", + ); + }); + }); +}); + +test("resolveConfig: maxLogBytes accepts 0 (unlimited) and ignores blank or invalid values", async () => { + const mod = await loadModule(); + const envCases: [string | undefined, unknown][] = [ + [undefined, 67108864], + ["0", 0], + ["2048", 2048], + ["", 67108864], // a blank env var must not silently disable the cap + ["nonsense", 67108864], + ["-5", 67108864], + ]; + for (const [value, expected] of envCases) { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", value, () => { + assert.equal( + mod.resolveConfig({ isProjectTrusted: () => false }).maxLogBytes, + expected, + `PI_BGRUN_MAX_LOG_BYTES=${JSON.stringify(value)}`, + ); + }); + } + + // The config-file layer: a non-negative number wins over the default; a + // negative one or a string is ignored rather than trusted. + const cfgFile = join(mkdtempSync(join(tmpdir(), "pi-bgrun-test-")), "user.json"); + try { + for (const [value, expected] of [ + [4096, 4096], + [-1, 67108864], + ["4096", 67108864], + ] as const) { + writeFileSync(cfgFile, JSON.stringify({ maxLogBytes: value })); + await withEnv("PI_BGRUN_USER_CONFIG", cfgFile, () => { + assert.equal( + mod.resolveConfig({ isProjectTrusted: () => false }).maxLogBytes, + expected, + `config maxLogBytes=${JSON.stringify(value)}`, + ); + }); + } + } finally { + rmSync(dirname(cfgFile), { recursive: true, force: true }); + } +}); + +// ── truncation is visible to the agent, not just on disk ─────────────────── + +test("formatBytes / parseTruncationFromContent: the notice counts only as the wrapper's own line", async () => { + const mod = await loadModule(); + assert.equal(mod.formatBytes(900), "900 bytes"); + assert.equal(mod.formatBytes(1000), "1000 bytes"); + assert.equal(mod.formatBytes(1536), "1.5 KiB"); + assert.equal(mod.formatBytes(67108864), "64 MiB"); + + // Real wrapper order: notice, then marker last. + assert.equal( + mod.parseTruncationFromContent("out\n\n[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n\n__BGRUN_EXIT__=0\n"), + 1000, + ); + // A running log (no marker yet) and a command that merely PRINTS the phrase + // are not evidence of truncation. + assert.equal( + mod.parseTruncationFromContent("[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n"), + null, + ); + assert.equal( + mod.parseTruncationFromContent("boom\n__BGRUN_EXIT__=1\n"), + null, + ); +}); + +test("wake: a capped job says so in the Stats line; an uncapped one does not", async () => { + const run = async (cap: string, command: string) => { + let wake = ""; + await withEnv("PI_BGRUN_MAX_LOG_BYTES", cap, async () => { + await withJobsDir(async (_dir, h) => { + await h.tools + .get("bgrun")! + .execute("call-wake-cap", { command, name: "j" }, undefined, undefined, h.ctx); + await waitForWakes(h.wakes, 1); + wake = h.wakes[0].text; + }); + }); + return wake; + }; + + const capped = await run("1000", SPEW_LINES); + assert.match(capped, /Stats: [\d.]+s, [\d,]+ lines, log truncated at 1000 bytes/); + + const plain = await run("1000000", "printf 'hello\\n'"); + assert.ok( + !plain.includes("log truncated"), + "no truncation claim for a log inside the cap", + ); + assert.match(plain, /Stats: [\d.]+s, 1 lines/); +}); + +test("wake digest: a scorecard is skipped, not misreported, when the log was capped", async () => { + const { dir, proj, home } = setupDigestEnv(); + try { + writeJson(join(proj, ".pi", "pi-bgrun.json"), { + digest: [{ label: "cap", command: "echo digest-ran" }], + }); + + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + const capped = await runDigestJob(proj, { + command: SPEW_LINES, + type: "test", + }); + const line = digestLineOf(capped); + assert.ok(line, "the digest line is still present"); + assert.match(line!, /^digest \(cap\): skipped — the log was truncated at 1000 bytes/); + assert.ok( + !capped.includes("digest-ran"), + "the scorecard never ran against a truncated log", + ); + }); + + // Under the cap the scorecard runs exactly as before. + const plain = await runDigestJob(proj, { + command: "printf 'hello\\n'", + type: "test", + }); + assert.match(digestLineOf(plain)!, /^digest \(cap\): digest-ran$/); + } finally { + teardownDigestEnv(dir, proj, home); + } +}); + +test("bgtail/bggrep: a capped log is labelled, and carries truncatedAtBytes", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1000", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const bgtail = tools.get("bgtail")!; + const bggrep = tools.get("bggrep")!; + + const res = await bgrun.execute( + "call-read-cap", + { command: "seq 1 400", name: "seq" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const tail = await bgtail.execute( + "call-read-cap", + { id, lines: 3 }, + undefined, + undefined, + ctx, + ); + assert.match( + tail.content[0].text as string, + /log truncated at 1000 bytes .*not the run's real end/, + ); + assert.equal(tail.details.truncatedAtBytes, 1000); + + // The dangerous case: failures past the cap look like "no failures". + const none = await bggrep.execute( + "call-read-cap", + { id, pattern: "^400$" }, + undefined, + undefined, + ctx, + ); + assert.match(none.content[0].text as string, /— none/); + assert.match( + none.content[0].text as string, + /output past the cap was never written and was not searched/, + ); + assert.equal(none.details.truncatedAtBytes, 1000); + }); + }); +}); + +test("bgtail/bggrep: no truncation label on an uncapped log", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const bgtail = tools.get("bgtail")!; + const bggrep = tools.get("bggrep")!; + + const res = await bgrun.execute( + "call-read-plain", + { command: "printf 'line1\\nline2\\n'", name: "plain" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const tail = await bgtail.execute( + "call-read-plain", + { id, lines: 2 }, + undefined, + undefined, + ctx, + ); + assert.ok(!(tail.content[0].text as string).includes("truncated")); + assert.equal(tail.details.truncatedAtBytes, undefined); + + const grep = await bggrep.execute( + "call-read-plain", + { id, pattern: "line1" }, + undefined, + undefined, + ctx, + ); + assert.ok(!(grep.content[0].text as string).includes("truncated")); + assert.equal(grep.details.truncatedAtBytes, undefined); + }); +}); + +test("bgtail/bggrep: a log bigger than the 2 MB read window says it was only partly searched", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const bgtail = tools.get("bgtail")!; + const bggrep = tools.get("bggrep")!; + + // ~2.7 MB — past LOG_READ_BYTES, so both readers see only the tail of it. + const res = await bgrun.execute( + "call-window", + { command: "seq 1 400000", name: "big" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const tail = await bgtail.execute( + "call-window", + { id, lines: 3 }, + undefined, + undefined, + ctx, + ); + assert.match( + tail.content[0].text as string, + /searched the last 2 MiB of [\d.]+ MiB — the earlier bytes were not searched/, + ); + + // "— none" on a >2 MB log must not read as "no failures anywhere". + const grep = await bggrep.execute( + "call-window", + { id, pattern: "^1$" }, + undefined, + undefined, + ctx, + ); + assert.match(grep.content[0].text as string, /— none/); + assert.match( + grep.content[0].text as string, + /the earlier bytes were not searched/, + ); + }); +}); + +test("bgtail/bggrep: no window caveat on a small log", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const res = await bgrun.execute( + "call-window-small", + { command: "printf 'a\\nb\\n'", name: "small" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + for (const tool of ["bgtail", "bggrep"] as const) { + const out = await tools.get(tool)!.execute( + "call-window-small", + tool === "bgtail" ? { id, lines: 2 } : { id, pattern: "a" }, + undefined, + undefined, + ctx, + ); + assert.ok( + !(out.content[0].text as string).includes("searched the last"), + `${tool}: no window caveat under the read bound`, + ); + } + }); +}); + +test("bggrep/bgtail: `bytes` widens the search window without widening the output", async () => { + await withJobsDir(async (_dir, h) => { + const { wakes, tools, ctx } = h; + const bgrun = tools.get("bgrun")!; + const bggrep = tools.get("bggrep")!; + const bgtail = tools.get("bgtail")!; + + // The marker is written FIRST, then ~2.7 MB of lines — so the default + // 2 MiB window cannot see it, and a widened window can. + const res = await bgrun.execute( + "call-bytes", + { command: "echo EARLY-MARKER; seq 1 400000", name: "wide" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + + const narrow = await bggrep.execute( + "call-bytes", + { id, pattern: "EARLY-MARKER" }, + undefined, + undefined, + ctx, + ); + assert.match(narrow.content[0].text as string, /— none/); + assert.match(narrow.content[0].text as string, /pass a larger `bytes`/); + assert.equal(narrow.details.windowBytes, 2 * 1024 * 1024); + + const wide = await bggrep.execute( + "call-bytes", + { id, pattern: "EARLY-MARKER", bytes: 8 * 1024 * 1024 }, + undefined, + undefined, + ctx, + ); + assert.match(wide.content[0].text as string, /L1: EARLY-MARKER/); + assert.equal(wide.details.windowBytes, 8 * 1024 * 1024); + // The claim that matters: scanning more does NOT mean returning more. + assert.ok( + (wide.content[0].text as string).length < 9000, + "output stays under the condenser cap", + ); + + // A window bigger than any job could write is clamped to the ceiling. + const huge = await bggrep.execute( + "call-bytes", + { id, pattern: "EARLY-MARKER", bytes: 1e15 }, + undefined, + undefined, + ctx, + ); + assert.equal(huge.details.windowBytes, 67108864); + + // bgtail: changing the window is a different VIEW, not appended output — + // it must reset to a full tail instead of claiming "+N new lines". + const first = await bgtail.execute( + "call-bytes", + { id, lines: 3 }, + undefined, + undefined, + ctx, + ); + assert.match(first.content[0].text as string, /400000/); + const rewidened = await bgtail.execute( + "call-bytes", + { id, lines: 3, bytes: 8 * 1024 * 1024 }, + undefined, + undefined, + ctx, + ); + assert.match( + rewidened.content[0].text as string, + /search window changed since last read/, + ); + assert.ok( + !rewidened.content[0].text.includes("new lines since last read"), + "no bogus delta after a window change", + ); + }); +}); + +test("clampReadWindow: default, explicit, garbage, and ceiling", async () => { + const mod = await loadModule(); + assert.equal(mod.clampReadWindow(undefined), 2097152); + assert.equal(mod.clampReadWindow(0), 2097152); + assert.equal(mod.clampReadWindow(-1), 2097152); + assert.equal(mod.clampReadWindow(Number.NaN), 2097152); + assert.equal(mod.clampReadWindow("8192"), 2097152); + assert.equal(mod.clampReadWindow(65536), 65536); + assert.equal(mod.clampReadWindow(65536.7), 65536); + assert.equal(mod.clampReadWindow(1e12), 67108864); +}); diff --git a/extension/index.ts b/extension/index.ts index 1df317b..7e38716 100644 --- a/extension/index.ts +++ b/extension/index.ts @@ -37,6 +37,7 @@ import { appendFileSync, closeSync, existsSync, + fstatSync, readSync, mkdirSync, openSync, @@ -67,14 +68,34 @@ const EXIT_MARKER = "__BGRUN_EXIT__="; const JOBS_DIR_MARKER = ".bgrun-jobs"; // Tail-read caps — avoid whole-file readFileSync on runaway logs. const LOG_TAIL_BYTES = 256 * 1024; // exit marker + last line -const LOG_READ_BYTES = 2 * 1024 * 1024; // bgtail / bggrep +const LOG_READ_BYTES = 2 * 1024 * 1024; // bgtail / bggrep default window const BGGREP_LINE_CAP = 10_000; // per-line match length cap +// Cap on the bytes a job may write to its log (stdout+stderr). Enforced inside +// the detached process tree, so it holds after pi exits. 0 = unlimited. +const DEFAULT_MAX_LOG_BYTES = 64 * 1024 * 1024; +// Upper bound for an explicit search window (bgtail/bggrep `bytes`). A job can +// never have written more than the ceiling, and the window is scanned in-process +// (bggrep ships the lines to a worker), so widening it costs CPU and memory — but +// NOT context: the returned text stays capped by the condenser (~8 KB). +const LOG_READ_BYTES_MAX = DEFAULT_MAX_LOG_BYTES; +// The wrapper appends this line (with a leading newline) when it had to drop +// output. Readers filter it exactly like EXIT_MARKER: wrapper bookkeeping, not +// job output, so it must not be counted as a content line or reported as the +// job's last line. +const TRUNC_NOTICE_PREFIX = "[pi-bgrun] output truncated"; + const DEFAULT_CLEANUP_DAYS = 7; const STALE_POLL_MS = 30_000; // re-check interval for jobs with no live child handle /** Default jobs dir inside a recognizable project root (`.git` or `.pi`). */ const PROJECT_LOCAL_JOBS_REL = ".pi-bgrun/jobs"; +// Files a spawn stages in the jobs dir under one shared +// `.tmp---` stem: the log itself (renamed to `.log` once the +// child pid is known) plus the wrapper's exit-code, fifo and byte-count files. +// Only these exact suffixes are ours — an unrelated `.tmp-*` is not. +const STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".cnt"]; + // Machine-global jobs dir. Resolved per call (not a module constant) so // PI_BGRUN_GLOBAL_DIR can redirect it — used by tests to stay off the real // ~/.pi-bgrun, and available for setups with a custom home or shared scratch. @@ -112,6 +133,16 @@ try { } `; +// Clamp a caller-supplied log search window: absent/garbage/non-positive → +// the default, anything wider than the ceiling → the ceiling (searching past +// what a job could have written is pure cost). +export function clampReadWindow(bytes: unknown): number { + if (typeof bytes !== "number" || !Number.isFinite(bytes) || bytes <= 0) { + return LOG_READ_BYTES; + } + return Math.min(Math.floor(bytes), LOG_READ_BYTES_MAX); +} + // Read at call time so tests (and users) can lower the budget; a non-positive // or non-numeric value falls back to the default. export function bggrepTimeoutMs(): number { @@ -269,6 +300,48 @@ export function parseExitFromLogPath(logPath: string): number | null { return parseExitFromContent(slice.content); } +// Wrapper bookkeeping lines — never job output. Every reader filters them, so a +// capped log's last line, line count, tail window and grep results still +// describe the COMMAND's output rather than the wrapper's own bookkeeping. +export function isWrapperLine(line: string): boolean { + return ( + line.startsWith(EXIT_MARKER) || line.startsWith(TRUNC_NOTICE_PREFIX) + ); +} + +// The byte ceiling a log actually hit, or null when it was not capped. Exact by +// construction: the notice only counts when it is the line immediately before +// the exit marker, which is the order the wrapper writes them in (marker last). +// A command that merely prints the phrase is not evidence of truncation. +export function parseTruncationFromContent(content: string): number | null { + const lines = content.split("\n"); + let i = lines.length - 1; + while (i >= 0 && lines[i].trim().length === 0) i--; + if (i < 0 || !lines[i].startsWith(EXIT_MARKER)) return null; + i--; + while (i >= 0 && lines[i].trim().length === 0) i--; + if (i < 0 || !lines[i].startsWith(TRUNC_NOTICE_PREFIX)) return null; + const match = lines[i].match(/ at (\d+) bytes \(first /); + return match ? parseInt(match[1], 10) : null; +} + +// The notice is written within the last few hundred bytes of the log (it +// precedes the exit marker), so the standard tail slice decides it — no full +// read, even for a log at the ceiling. +function readTruncationBytes(logPath: string): number | null { + const slice = readLogSlice(logPath, LOG_TAIL_BYTES); + if (!slice) return null; + return parseTruncationFromContent(slice.content); +} + +// Compact byte size for the wake and reader notes ("64 MiB", "1.5 KiB", +// "900 bytes"). One decimal is enough: this labels a ceiling, not a quantity. +export function formatBytes(n: number): string { + if (n >= 1024 * 1024) return `${Math.round((n / (1024 * 1024)) * 10) / 10} MiB`; + if (n >= 1024) return `${Math.round((n / 1024) * 10) / 10} KiB`; + return `${n} bytes`; +} + function readLastLogLine(logPath: string, maxLen = 200): string | null { const slice = readLogSlice(logPath, LOG_TAIL_BYTES); if (!slice) return null; @@ -278,7 +351,7 @@ function readLastLogLine(logPath: string, maxLen = 200): string | null { function readLastLineFromContent(content: string, maxLen = 200): string | null { const lines = content.split("\n").filter((l) => l.trim().length > 0); if (lines.length === 0) return null; - const real = lines.filter((l) => !l.startsWith(EXIT_MARKER)); + const real = lines.filter((l) => !isWrapperLine(l)); // No content lines (a marker-only log) → nothing to show. Never fall back to // the exit-marker line — that leaks "__BGRUN_EXIT__=N" into the wake. if (real.length === 0) return null; @@ -482,6 +555,11 @@ interface BgrunConfig { showCompletedJobs: boolean; // Log retention for cleanup (auto-sweeps and the bgclean default). cleanupDays: number; + // Byte ceiling for a job's log (stdout+stderr). A runaway job (`yes`, a spew + // loop) would otherwise fill the disk. The cap keeps the FIRST maxLogBytes + // bytes and appends a truncation notice; the job itself runs to completion + // with its real exit code. 0 = unlimited. Read per job at spawn time. + maxLogBytes: number; // Auto-sweep the shared jobs dirs at session boundaries for orphans — // finished (exit marker or dead pid) logs older than cleanupDays from // sessions that crashed or are never resumed again. Both the machine-global @@ -510,6 +588,7 @@ interface BgrunConfigFile { adoptForeignJobs?: unknown; showCompletedJobs?: unknown; cleanupDays?: unknown; + maxLogBytes?: unknown; globalAutoClean?: unknown; digest?: unknown; } @@ -544,6 +623,51 @@ function readConfigFile(path: string): BgrunConfigFile { return {}; } +// ── Job wrapper ───────────────────────────────────────────────────────────── +// +// Every job runs inside a detached `sh -c` tree, so the log ceiling has to live +// there too — it must hold after pi exits. The command is passed as argv ($1), +// never interpolated, or `#`, quotes and heredocs would break. +// +// Capped shape: the command's output is tee'd into a byte counter and piped +// through `head -c` into the log, with `cat >/dev/null` draining the rest so the +// producer never gets SIGPIPE — the job runs to completion and keeps its real +// exit code. That code travels through a file, not the pipe, because a +// pipeline's `$?` is the reader's. +// +// Why the count comes from a tee'd copy instead of "what head left behind": +// `head -c` reads into a buffer and discards the excess, so the remainder +// under-reports (measured on macOS: a 1500-byte stream capped at 1000 leaves 0, +// not 500). Sizing the log fd directly is no better — it is opened O_WRONLY, so +// reopening /dev/fd/1 fails with EACCES. `wc -c` on an uncapped copy is exact. +// +// If `mkfifo` fails, fall back to the uncapped path: losing output is worse +// than losing the ceiling. +// +// argv: $1 command, $2 ecfile, $3 fifo, $4 countfile. +export function cappedWrapper(maxBytes: number): string { + const cap = String(maxBytes); + return [ + `if mkfifo "$3" 2>/dev/null; then`, + ` rm -f "$4"; ( wc -c <"$3" >"$4" ) & ctr=$!`, + ` { sh -c "$1" 2>&1; ec=$?; printf '%d' "$ec" >"$2"; } | tee "$3" | { head -c ${cap}; cat >/dev/null; }`, + ` wait "$ctr"`, + ` total=$(tr -d '[:space:]' <"$4" 2>/dev/null)`, + ` rm -f "$3" "$4"`, + ` if [ "\${total:-0}" -gt ${cap} ]; then`, + ` printf '\\n${TRUNC_NOTICE_PREFIX} at %s bytes (first %s bytes kept)\\n' ${cap} ${cap}`, + ` fi`, + ` ec=$(cat "$2" 2>/dev/null)`, + `else`, + ` sh -c "$1" 2>&1`, + ` ec=$?`, + `fi`, + `rm -f "$2"`, + `[ -n "$ec" ] || ec=-1`, + `printf '\\n${EXIT_MARKER}%d\\n' "$ec"; exit "$ec"`, + ].join("\n"); +} + // ── Project-local jobs dir ────────────────────────────────────────────────── // // By default, when the session cwd is inside a recognizable project root @@ -955,6 +1079,24 @@ export function resolveConfig(ctx?: { : undefined; const envDays = Number(process.env.PI_BGRUN_CLEANUP_DAYS); const daysEnv = Number.isFinite(envDays) && envDays > 0 ? envDays : undefined; + // Byte ceiling: unlike cleanupDays, 0 is meaningful ("unlimited"), so it is + // accepted — but a BLANK env var is not, or an empty + // PI_BGRUN_MAX_LOG_BYTES= would silently disable the cap. + const maxBytesFile = + typeof merged.maxLogBytes === "number" && + Number.isFinite(merged.maxLogBytes) && + merged.maxLogBytes >= 0 + ? Math.floor(merged.maxLogBytes) + : undefined; + const maxBytesRaw = process.env.PI_BGRUN_MAX_LOG_BYTES; + const maxBytesEnvValue = + maxBytesRaw === undefined || maxBytesRaw.trim() === "" + ? NaN + : Number(maxBytesRaw); + const maxBytesEnv = + Number.isFinite(maxBytesEnvValue) && maxBytesEnvValue >= 0 + ? Math.floor(maxBytesEnvValue) + : undefined; const { dir: jobsDir, projectLocal: jobsDirProjectLocal } = resolveJobsDirPath(process.env.PI_BGRUN_DIR || dirFile, ctx); // Digest section: accept either the legacy single-object form (normalized to @@ -1001,6 +1143,7 @@ export function resolveConfig(ctx?: { completedFile ?? false, cleanupDays: daysEnv ?? daysFile ?? DEFAULT_CLEANUP_DAYS, + maxLogBytes: maxBytesEnv ?? maxBytesFile ?? DEFAULT_MAX_LOG_BYTES, globalAutoClean: parseBoolEnv(process.env.PI_BGRUN_GLOBAL_AUTO_CLEAN) ?? globalCleanFile ?? @@ -1089,6 +1232,23 @@ interface BgStatusDetails { export default function (pi: ExtensionAPI) { const jobs = new Map(); + // bgtail's delta-tailing bookmarks: one entry per job id ever tailed, holding + // the high-water mark of what the caller has already had the opportunity to + // see. Declared here, ahead of the cleanup helpers, so removing a log can + // evict its bookmark. TAIL_BOOKMARK_CAP bounds the rest — cleanup only evicts + // jobs whose log it removed, and a long session that tails many job ids + // (foreign ones are never cleaned here) would otherwise grow it forever. + const TAIL_BOOKMARK_CAP = 1_000; + // A bookmark is the high-water mark of what the caller has seen PLUS the + // search window it was seen through: the same log read through a wider window + // is a different view, not newly appended output. + type TailBookmark = { + lines: number; + bytes: number; + first: string; + window: number; + }; + const tailBookmarks = new Map(); // Poller for stale job records — anything running with no live ChildProcess // handle (adopted foreign jobs + jobs reconstructed from transcript entries // after a restart). No exit event exists for those, so their logs/pids are @@ -1127,6 +1287,12 @@ export default function (pi: ExtensionAPI) { return normalizeType(type); } + // Hard read bound for the line-count scan. The ceiling normally keeps logs + // small, but `maxLogBytes: 0` (unlimited) and logs from a run with a higher + // ceiling still reach here, and this runs on the main thread at every job + // exit. Past the bound the count is omitted rather than reported wrong. + const COUNT_SCAN_MAX_BYTES = 64 * 1024 * 1024; + // Count the log's total lines with a bounded-memory streaming scan (one // fixed-size buffer, no full-file read). Missing/unreadable file → null: // the Stats line then just omits the line count — best-effort, never @@ -1139,19 +1305,26 @@ export default function (pi: ExtensionAPI) { return null; } try { + // fstat, not the scan's own progress: the tail pread below is positioned + // by the REAL file size, so bounding the scan can never misplace it. + const size = fstatSync(fd).size; + if (size === 0) return 0; + if (size > COUNT_SCAN_MAX_BYTES) return null; const buf = Buffer.alloc(64 * 1024); let newlines = 0; - let size = 0; + let seen = 0; let bytesRead = 0; do { bytesRead = readSync(fd, buf, 0, buf.length, null); if (bytesRead <= 0) break; - size += bytesRead; + seen += bytesRead; for (let i = 0; i < bytesRead; i++) { if (buf[i] === 0x0a) newlines++; } } while (bytesRead === buf.length); - if (size === 0) return 0; + // A log that changed size mid-scan (rotated, or appended by a resumed + // job) would produce a count that matches neither state. + if (seen !== size) return null; // One bounded pread of the tail for the final-byte + exit-marker check. const tailLen = Math.min(size, 512); const tail = Buffer.alloc(tailLen); @@ -1159,20 +1332,25 @@ export default function (pi: ExtensionAPI) { const tailText = tail.toString("latin1"); const endsWithNewline = tailText.charCodeAt(tailText.length - 1) === 0x0a; let count = newlines + (endsWithNewline ? 0 : 1); - // The wrapper appends "\n\n" — those newlines are not - // command output. Drop the marker line, plus the blank separator when the - // output already ended in a newline. + // The wrapper appends "\n\n" — and, when it had to drop + // output, "\n\n" before that. Those newlines are not command + // output. Drop the whole trailing wrapper block, including its leading + // separator when the output already ended in a newline. const markerAt = tailText.lastIndexOf("\n" + EXIT_MARKER); if (markerAt === 0) { // The file is only the wrapper's "\n\n" — no command output. return 0; } if (markerAt !== -1) { + const noticeAt = tailText.lastIndexOf("\n" + TRUNC_NOTICE_PREFIX); + const blockStart = + noticeAt !== -1 && noticeAt < markerAt ? noticeAt : markerAt; let extra = 0; - for (let i = markerAt + 1; i < tailText.length; i++) { + for (let i = blockStart + 1; i < tailText.length; i++) { if (tailText.charCodeAt(i) === 0x0a) extra++; } - if (markerAt > 0 && tailText.charCodeAt(markerAt - 1) === 0x0a) extra++; + if (blockStart > 0 && tailText.charCodeAt(blockStart - 1) === 0x0a) + extra++; count = Math.max(0, count - extra); } return count; @@ -1228,9 +1406,12 @@ export default function (pi: ExtensionAPI) { if ( !name.startsWith(".bgrun-used-") && !name.startsWith(".digest-nudge-") && - // Only OUR staging files (`.tmp---.log`), never an - // unrelated `.tmp-*` that happens to live in the dir. - !(name.startsWith(".tmp-") && name.endsWith(".log")) + // Only OUR staging files (`.tmp---.log|.ec|.fifo|.cnt`), + // never an unrelated `.tmp-*` that happens to live in the dir. + !( + name.startsWith(".tmp-") && + STAGING_SUFFIXES.some((suffix) => name.endsWith(suffix)) + ) ) continue; try { @@ -1287,6 +1468,9 @@ export default function (pi: ExtensionAPI) { try { unlinkSync(entry.logPath); result.removed++; + // The log is gone: its delta bookmark would otherwise pin a stale + // high-water mark (and a Map slot) for the life of the session. + tailBookmarks.delete(entry.id); } catch { // ignore } @@ -1326,6 +1510,7 @@ export default function (pi: ExtensionAPI) { // (and its ExtensionContext) for the life of the process. if (rec.exitedAt !== undefined && rec.exitedAt < cutoff) { jobs.delete(rec.id); + tailBookmarks.delete(rec.id); } continue; } @@ -1337,6 +1522,7 @@ export default function (pi: ExtensionAPI) { unlinkSync(rec.logPath); result.removed++; jobs.delete(rec.id); + tailBookmarks.delete(rec.id); } catch { // ignore } @@ -1745,10 +1931,8 @@ export default function (pi: ExtensionAPI) { // log fd must exist before spawn. Create at a temp path, rename after spawn. // randomBytes (not Math.random) plus O_EXCL: the temp name is not // guessable and a pre-planted symlink cannot be truncated through. - const tmpPath = join( - jobsDir, - `.tmp-${slug}-${ts}-${randomBytes(4).toString("hex")}.log`, - ); + const stem = `.tmp-${slug}-${ts}-${randomBytes(4).toString("hex")}`; + const tmpPath = join(jobsDir, `${stem}.log`); let logFd: number | undefined; let logPath = tmpPath; try { @@ -1761,11 +1945,31 @@ export default function (pi: ExtensionAPI) { } try { // Pass command as argv — interpolation breaks on #, quotes, heredocs. - const wrapper = `sh -c "$1"; ec=$?; printf '\\n${EXIT_MARKER}%d\\n' "$ec"; exit "$ec"`; - const child = spawn("sh", ["-c", wrapper, "bgrun", command], { - stdio: ["ignore", logFd, logFd], - detached: true, - }); + // maxLogBytes 0 means "unlimited": keep the pre-ceiling wrapper exactly + // (head -c 0 is a hard error, not a no-op, so it cannot be routed + // through the capped path). + const capped = cfg.maxLogBytes > 0; + const wrapper = capped + ? cappedWrapper(cfg.maxLogBytes) + : `sh -c "$1"; ec=$?; printf '\\n${EXIT_MARKER}%d\\n' "$ec"; exit "$ec"`; + const child = spawn( + "sh", + capped + ? [ + "-c", + wrapper, + "bgrun", + command, + join(jobsDir, `${stem}.ec`), + join(jobsDir, `${stem}.fifo`), + join(jobsDir, `${stem}.cnt`), + ] + : ["-c", wrapper, "bgrun", command], + { + stdio: ["ignore", logFd, logFd], + detached: true, + }, + ); child.unref(); const childPid = child.pid ?? -1; @@ -1887,6 +2091,12 @@ export default function (pi: ExtensionAPI) { const statsParts = [formatDuration(rec.exitedAt - rec.started)]; if (logLines !== null) statsParts.push(`${logLines.toLocaleString("en-US")} lines`); + // The cap is the one fact that changes what the others MEAN: the line + // count, the last line and any digest describe only the bytes that + // were kept. Say so in the line the agent reads first. + const truncatedAt = readTruncationBytes(logPath); + if (truncatedAt !== null) + statsParts.push(`log truncated at ${formatBytes(truncatedAt)}`); // Persist the done-state entry. pi.appendEntry("bgrun-job", { @@ -1926,9 +2136,21 @@ export default function (pi: ExtensionAPI) { }; const selected = selectDigestEntry(digestEntries, digestTarget); if (selected) { - const raw = await runDigestCommand(selected.command, logPath); - const text = raw === undefined ? undefined : capDigestOutput(raw); - if (text) digestBlock = { label: selected.label, text }; + if (truncatedAt !== null) { + // A scorecard reads the log's END (summary lines, failure + // lists) — exactly what a head cap drops. Its numbers would be + // confidently wrong, so report why it was skipped instead. + digestBlock = { + label: selected.label, + text: + `skipped — the log was truncated at ${formatBytes(truncatedAt)} ` + + "and this scorecard reads the log's end, which the cap dropped", + }; + } else { + const raw = await runDigestCommand(selected.command, logPath); + const text = raw === undefined ? undefined : capDigestOutput(raw); + if (text) digestBlock = { label: selected.label, text }; + } } else if (digestEntries?.length) { // Configured but nothing selected — otherwise silent. Surface the // job's type/name plus the configured types, once per distinct @@ -2249,13 +2471,17 @@ export default function (pi: ExtensionAPI) { // for lines already seen. Deliberately-skipped prefix lines are never // replayed as "new". raw: true keeps the verbatim last-N window (no delta // header) but still advances the bookmark. A shrunken log (rotated/replaced) - // resets to a full tail. Bookmarks are in-memory only — a session restart - // starts fresh with a full tail. - - const tailBookmarks = new Map< - string, - { lines: number; bytes: number; first: string } - >(); + // resets to a full tail. Bookmarks are in-memory only (see tailBookmarks + // above) — a session restart starts fresh with a full tail. + + // Record a bookmark, evicting the oldest entry once the map is full. Cleanup + // drops bookmarks when it removes a log; this bounds the rest. + function rememberTail(id: string, bookmark: TailBookmark): void { + tailBookmarks.set(id, bookmark); + if (tailBookmarks.size <= TAIL_BOOKMARK_CAP) return; + const oldest = tailBookmarks.keys().next().value; + if (oldest !== undefined && oldest !== id) tailBookmarks.delete(oldest); + } // Resolve a job's log path and read its bounded slice, single-sourcing the // "in-memory record first, then the configured jobs dir" rule shared by @@ -2265,14 +2491,15 @@ export default function (pi: ExtensionAPI) { function resolveLogForJob( id: string, tool: string, - ctx?: ExtensionContext, + ctx: ExtensionContext | undefined, + window: number, ): | { logPath: string; content: string; size: number } | { logPath: string; errorText: string; notFound: boolean } { validateJobId(id, tool); const logPath = jobs.get(id)?.logPath ?? join(resolveConfig(ctx).jobsDir, `${id}.log`); - const slice = readLogSlice(logPath, LOG_READ_BYTES); + const slice = readLogSlice(logPath, window); if (!slice) { return { logPath, @@ -2286,7 +2513,7 @@ export default function (pi: ExtensionAPI) { // Shared by the bgtail tool (agent-facing) and the /bgtail slash command // (human-facing). async function bgtailCore( - params: { id: string; lines?: number; raw?: boolean }, + params: { id: string; lines?: number; raw?: boolean; bytes?: number }, ctx?: ExtensionContext, ): Promise<{ content: { type: "text"; text: string }[]; @@ -2298,7 +2525,8 @@ export default function (pi: ExtensionAPI) { // tool schema, and lines < 1 would corrupt slicing (slice(-0) = whole log). const lines = Math.max(1, Math.floor(linesParam)); if (!id) throw new Error("bgtail: id is required"); - const resolved = resolveLogForJob(id, "bgtail", ctx); + const readWindow = clampReadWindow(params.bytes); + const resolved = resolveLogForJob(id, "bgtail", ctx, readWindow); if ("errorText" in resolved) { return { content: [{ type: "text", text: resolved.errorText }], @@ -2311,49 +2539,82 @@ export default function (pi: ExtensionAPI) { }; } const { logPath, content, size } = resolved; - // Content lines only: the exit marker and blanks are filtered BEFORE the - // window is sliced, so "last N lines" means the last N content lines - // (matching pre-delta behavior) and bookmarks count content lines. + // The cap dropped bytes off the END, so every "last N lines" view below is + // the end of what was KEPT. Flag it in the output, or a mid-run line reads + // as the job's final word — and in the details, for callers that parse them. + const truncatedAt = parseTruncationFromContent(content); + const capNote = + truncatedAt === null + ? "" + : `\n\n(log truncated at ${formatBytes(truncatedAt)} — lines past the cap were never written, so this is not the run's real end)`; + const truncDetails = + truncatedAt === null ? {} : { truncatedAtBytes: truncatedAt }; + // Tail reads are bounded at LOG_READ_BYTES, so on a log past that window + // every view above is the end of a 2 MB slice — say so, or "not in the + // output" reads as "not in the log". + const windowNote = + size > readWindow + ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(LOG_READ_BYTES_MAX)}) or use ctx_execute_file on the log path)` + : ""; + // Content lines only: wrapper bookkeeping (exit marker, truncation notice) + // and blanks are filtered BEFORE the window is sliced, so "last N lines" + // means the last N content lines (matching pre-delta behavior) and + // bookmarks count content lines. // /\r?\n/ keeps CRLF logs from leaving a stray \r on every line. const rawLines = content .split(/\r?\n/) - .filter((l) => !l.startsWith(EXIT_MARKER) && l.trim().length > 0); + .filter((l) => !isWrapperLine(l) && l.trim().length > 0); const total = rawLines.length; const first = rawLines[0]?.slice(0, 200) ?? ""; const prev = tailBookmarks.get(id); + // Same log, different window: a wider view would look like pages of "new" + // lines that were only never looked at before, so reset the delta. It also + // moves the window's first line, so it must be tested BEFORE the + // replacement heuristic below — otherwise a widened read misreports the log + // as replaced. + const windowChanged = prev !== undefined && prev.window !== readWindow; // Append-only logs never mutate earlier lines, so a changed first // content line means the log was replaced or rotated — reset to a full // tail. Catches same-size replacements the shrink checks cannot see. // (A previously-empty log growing content is growth, not replacement.) const replaced = - prev !== undefined && prev.lines > 0 && prev.first !== first; + prev !== undefined && + !windowChanged && + prev.lines > 0 && + prev.first !== first; const shrank = prev !== undefined && (prev.lines > total || prev.bytes > size); let window: string[]; let header: string | undefined; let newLines: number | undefined; - if (raw || prev === undefined || shrank || replaced) { - // Full tail: first read, raw mode, or a shrunken/replaced log (reset). + if (raw || prev === undefined || shrank || replaced || windowChanged) { + // Full tail: first read, raw mode, a shrunken/replaced log, or a changed + // search window (all resets). window = rawLines.slice(-lines); - if (!raw && (shrank || replaced)) { + if (!raw) { header = shrank ? "log shrank since last read — showing full tail" - : "log was replaced since last read — showing full tail"; + : replaced + ? "log was replaced since last read — showing full tail" + : windowChanged + ? "search window changed since last read — showing full tail" + : undefined; } } else { const fresh = rawLines.slice(prev.lines); newLines = fresh.length; if (fresh.length === 0) { - tailBookmarks.set(id, { + rememberTail(id, { lines: total, bytes: size, first, + window: readWindow, }); return { content: [ { type: "text", - text: `(no new lines since last read — log at ${total} line${total === 1 ? "" : "s"})`, + text: `(no new lines since last read — log at ${total} line${total === 1 ? "" : "s"})${capNote}${windowNote}`, }, ], details: { @@ -2364,6 +2625,8 @@ export default function (pi: ExtensionAPI) { condensed: true, newLines: 0, totalLines: total, + windowBytes: readWindow, + ...truncDetails, }, }; } @@ -2372,10 +2635,11 @@ export default function (pi: ExtensionAPI) { `+${fresh.length} new line${fresh.length === 1 ? "" : "s"} since last read — ` + `log at ${total} lines${fresh.length > lines ? ` (showing last ${lines})` : ""}`; } - tailBookmarks.set(id, { + rememberTail(id, { lines: total, bytes: size, first, + window: readWindow, }); const shown = window; const { text, truncated } = condenseLogLines(shown, { raw }); @@ -2385,7 +2649,12 @@ export default function (pi: ExtensionAPI) { const notes = truncated.length > 0 ? `\n\n(${truncated.join("; ")})` : ""; const head = header ? `${header}\n` : ""; return { - content: [{ type: "text", text: head + body + notes }], + content: [ + { + type: "text", + text: head + body + notes + capNote + windowNote, + }, + ], details: { id, linesShown: shown.length, @@ -2394,6 +2663,8 @@ export default function (pi: ExtensionAPI) { condensed: !raw, ...(newLines === undefined ? {} : { newLines, totalLines: total }), ...(truncated.length > 0 ? { condenserNotes: truncated } : {}), + windowBytes: readWindow, + ...truncDetails, }, }; } @@ -2402,7 +2673,7 @@ export default function (pi: ExtensionAPI) { name: "bgtail", label: "Tail Background Log", description: - "Read the newest lines of a background job's log, condensed for context: ANSI escapes stripped, repeated lines collapsed, long lines truncated, output capped (~8KB). Strips the exit-marker line. The first read returns the last N lines (default 40); REPEAT reads return only lines appended since your last read (delta tailing) — polling a running job never re-pays for the same lines. raw: true returns the unprocessed last-N window. A shrunken or replaced log resets to a full tail. For pattern search use bggrep; for whole-log analysis, ctx_execute_file on the log path.", + "Read the newest lines of a background job's log, condensed for context: ANSI escapes stripped, repeated lines collapsed, long lines truncated, output capped (~8KB). Strips the exit-marker line. The first read returns the last N lines (default 40); REPEAT reads return only lines appended since your last read (delta tailing) — polling a running job never re-pays for the same lines. raw: true returns the unprocessed last-N window. A shrunken, replaced, or differently-windowed log resets to a full tail. Reads only the log's last 2 MiB by default (`bytes` widens it, max 64 MiB) and says so when the log is bigger. For pattern search use bggrep; for whole-log analysis, ctx_execute_file on the log path.", promptSnippet: "Read the last N lines of a bgrun job's log", parameters: Type.Object({ id: Type.String({ @@ -2420,6 +2691,13 @@ export default function (pi: ExtensionAPI) { "Skip condensing (ANSI strip, collapse, caps) and return raw text", }), ), + bytes: Type.Optional( + Type.Number({ + description: + "Search window in bytes (default 2097152 = 2 MiB, max 67108864 = 64 MiB). Widening only affects how much is SCANNED — the returned text stays capped.", + minimum: 1, + }), + ), }), async execute(_toolCallId, params, _signal, _onUpdate, ctx) { return bgtailCore(params, ctx); @@ -2428,18 +2706,19 @@ export default function (pi: ExtensionAPI) { // ── bggrep: pattern search over a job's log, capped for context ─────────── // - // The sandboxed whole-log path (ctx_execute_file) is confined to the - // project root, which a global jobs dir sits outside of — bggrep runs - // inside the extension with native fs access, so it reaches the configured - // jobs dir (including a global one). Matches are line-numbered (grep -n style), + // bggrep runs inside the extension, so it resolves the job id to the + // configured jobs dir itself (no path to reconstruct) and needs no shell + // quoting for the regex; ctx_execute_file can read the same file, but you + // must hand it the absolute path. Matches are line-numbered (grep -n style), // optionally with context lines, capped at MAX_GREP_MATCHES, and run // through the same condenser as bgtail so a search can never flood context. const MAX_GREP_MATCHES = 50; async function bggrepCore( - params: { id: string; pattern?: string; context?: number }, + params: { id: string; pattern?: string; context?: number; bytes?: number }, ctx?: ExtensionContext, + ): Promise<{ content: { type: "text"; text: string }[]; details: Record; @@ -2461,7 +2740,8 @@ export default function (pi: ExtensionAPI) { ); } // Record-first, same as bgtail — correct across config changes. - const resolved = resolveLogForJob(id, "bggrep", ctx); + const readWindow = clampReadWindow(params.bytes); + const resolved = resolveLogForJob(id, "bggrep", ctx, readWindow); if ("errorText" in resolved) { return { content: [{ type: "text", text: resolved.errorText }], @@ -2474,13 +2754,29 @@ export default function (pi: ExtensionAPI) { isError: true, }; } - const { logPath, content } = resolved; + const { logPath, content, size } = resolved; + // A capped log is missing its END, and "no matches" is exactly what a + // failure pattern looks like when the failures were past the cap — so the + // note belongs next to the count, not just in the details. + const truncatedAt = parseTruncationFromContent(content); + const truncNote = + truncatedAt === null + ? "" + : `\n\n(log truncated at ${formatBytes(truncatedAt)} — output past the cap was never written and was not searched)`; + const truncDetails = + truncatedAt === null ? {} : { truncatedAtBytes: truncatedAt }; + // Same window caveat as bgtail: the search covers only the last `window` + // bytes, so a miss on a bigger log means "not in the searched slice". + const windowNote = + size > readWindow + ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(LOG_READ_BYTES_MAX)}) or use ctx_execute_file on the log path)` + : ""; // /\r?\n/ normalizes CRLF (a trailing \r would break $-anchored patterns // and leak into output); blank lines are KEPT so L numbers match the // file. A trailing empty split element is dropped; "" yields zero lines. const split = content === "" ? [] : content.split(/\r?\n/); if (split.length > 0 && split[split.length - 1] === "") split.pop(); - const rawLines = split.filter((l) => !l.startsWith(EXIT_MARKER)); + const rawLines = split.filter((l) => !isWrapperLine(l)); // Match under a wall-clock budget in a worker: a caller-supplied regex can // backtrack catastrophically and would otherwise hang the main thread with // no way to interrupt it. @@ -2515,6 +2811,8 @@ export default function (pi: ExtensionAPI) { notFound: false, pattern: source, timedOut: true, + windowBytes: readWindow, + ...truncDetails, }, isError: true, }; @@ -2525,13 +2823,17 @@ export default function (pi: ExtensionAPI) { `in ${rawLines.length} line${rawLines.length === 1 ? "" : "s"}`; if (matchIdx.length === 0) { return { - content: [{ type: "text", text: `${header} — none` }], + content: [ + { type: "text", text: `${header} — none${truncNote}${windowNote}` }, + ], details: { id, matches: 0, linesSearched: rawLines.length, logPath, notFound: false, + windowBytes: readWindow, + ...truncDetails, }, }; } @@ -2561,7 +2863,12 @@ export default function (pi: ExtensionAPI) { ? ` — showing first ${MAX_GREP_MATCHES}; ${matchIdx.length - MAX_GREP_MATCHES} more not shown` : ""; return { - content: [{ type: "text", text: `${header}${capNote}\n${text}${notes}` }], + content: [ + { + type: "text", + text: `${header}${capNote}\n${text}${notes}${truncNote}${windowNote}`, + }, + ], details: { id, matches: matchIdx.length, @@ -2570,6 +2877,8 @@ export default function (pi: ExtensionAPI) { notFound: false, pattern: source, capped, + windowBytes: readWindow, + ...truncDetails, }, }; } @@ -2578,7 +2887,7 @@ export default function (pi: ExtensionAPI) { name: "bggrep", label: "Grep Background Log", description: - "Search the last 2 MB of a background job's log with a regex (each line is pre-truncated to 10k chars before matching); returns only matching lines with line numbers (optional context lines), capped (~50 matches, ~8KB) and condensed. Matching runs under a wall-clock budget (default 2s, PI_BGRUN_GREP_TIMEOUT_MS), so a runaway regex fails instead of hanging. Runs inside the extension, so it reaches the configured jobs dir (including a global one) that project-sandboxed tools (ctx_execute_file) cannot reach. Pass your own pattern whenever you know the log's format; with no pattern a generic failure-signature default is used (a convenience only — not a guarantee).", + "Search the tail of a background job's log with a regex — the last 2 MiB by default, widen with `bytes` (each line is pre-truncated to 10k chars before matching); returns only matching lines with line numbers (optional context lines), capped (~50 matches, ~8KB) and condensed. Matching runs under a wall-clock budget (default 2s, PI_BGRUN_GREP_TIMEOUT_MS), so a runaway regex fails instead of hanging. Resolves the job id to the configured jobs dir itself, so there is no log path to reconstruct; ctx_execute_file can read the same file, but needs the absolute path. Pass your own pattern whenever you know the log's format; with no pattern a generic failure-signature default is used (a convenience only — not a guarantee).", promptSnippet: "Search a bgrun job's log for a pattern", promptGuidelines: [ "Never search a bgrun log with the bash tool — uncapped output can flood context, and it needs manual log-path reconstruction and regex shell-quoting; bggrep is bounded by design.", @@ -2602,6 +2911,13 @@ export default function (pi: ExtensionAPI) { minimum: 0, }), ), + bytes: Type.Optional( + Type.Number({ + description: + "Search window in bytes (default 2097152 = 2 MiB, max 67108864 = 64 MiB). Widening only affects how much is SCANNED — the returned matches stay capped (~50 matches, ~8KB).", + minimum: 1, + }), + ), }), async execute(_toolCallId, params, _signal, _onUpdate, ctx) { return bggrepCore(params, ctx); diff --git a/skill/run-bg/SKILL.md b/skill/run-bg/SKILL.md index 074e920..afced7f 100644 --- a/skill/run-bg/SKILL.md +++ b/skill/run-bg/SKILL.md @@ -50,7 +50,8 @@ no polling. - `done exit=` → failure; analyze the log. - `running` but the job should have finished long ago → likely crashed (the process died without writing the exit marker). Analyze the log with - `bggrep` (any jobs dir) or `ctx_execute_file` (project-local logs only). + `bggrep` (any jobs dir, last 2 MB) or `ctx_execute_file` on the absolute path + (whole file — needed for logs bigger than 2 MB). ### Reading results without flooding context @@ -62,15 +63,18 @@ usually answers "what failed" without any follow-up read. `bgtail` stays the positional-peek tool for everything else. - **Quick peek (≤40 lines):** call `bgtail` with the job id and `lines: 40` — strips the `__BGRUN_EXIT__` marker. The first read returns the last-40 tail; repeat reads return only lines appended since your last read (delta tailing) — polling a running job is nearly free. -- **Failure extraction:** `bggrep(, "pattern")` — line-numbered matches with optional context lines, capped and condensed. Reaches the configured jobs dir (including a global one) that project-sandboxed `ctx_execute_file` cannot (it runs inside the extension). Pass your own pattern whenever you know the tool's output format; the default only catches common failure signatures. -- **Whole-log failure analysis:** `ctx_execute_file` on the log path — **project-local - `jobsDir` only** (e.g. `.pi-bgrun/jobs` in `pi-bgrun.json`). The default global - dir (`~/.pi-bgrun/jobs`) is outside the project sandbox; use `bggrep` there instead. - Copy the `log:` path from `bgrun`'s `started:` line (do not use `~` — it may not expand). +- **Failure extraction:** `bggrep(, "pattern")` — line-numbered matches with optional context lines, capped and condensed. Resolves the job id to the configured jobs dir itself — no path to reconstruct. (`ctx_execute_file` can read the same file given its absolute path.) Searches the last 2 MiB by default; `bytes: 67108864` widens it to the whole capped log — more scanning costs latency and memory, **not context**, since the returned matches stay capped. Pass your own pattern whenever you know the tool's output format; the default only catches common failure signatures. +- **Whole-log failure analysis:** `ctx_execute_file` on the log's **absolute + path**. Unlike `bgtail`/`bggrep` (bounded to the last 2 MB), this reads the + whole file — the only way to cover a log bigger than 2 MB, e.g. one that hit + the size ceiling. Copy the `log:` path from `bgrun`'s `started:` line and + expand `~` yourself (it is not expanded for you; the tool takes an absolute + path or one relative to the project root). Otherwise it is an ordinary tool + call: your normal Read-deny rules still apply. ```javascript ctx_execute_file( - path: "/.pi-bgrun/jobs/.log", + path: "/Users/me/project/.pi-bgrun/jobs/.log", language: "javascript", code: "const L=FILE_CONTENT.split('\\n'); \ const fails=L.filter(l=>/(--- FAIL|FAIL|panic:|Error:)/.test(l)); \ @@ -90,8 +94,7 @@ positional-peek tool for everything else. ~8KB, plus a wall-clock match budget so a runaway regex errors instead of hanging). - It takes the job id — no log-path reconstruction, no shell-quoting of the - regex — and reaches the configured jobs dir (including a global one) that - project-sandboxed `ctx_execute_file` cannot. + regex, and no reliance on the agent getting `~` expansion right. - Output is self-describing: match count, line numbers, `…[N skipped]…` gap markers, `— none` for no-match. @@ -100,6 +103,24 @@ Plain `grep` via bash is fine only for a one-off search you know is tiny. **Never `cat`, `Read`, `bash cat`, or `bash grep` a full bgrun log.** Always `bgtail`, `bggrep`, or (for project-local logs) `ctx_execute_file`. +**Order of preference, cheapest first: `bgtail` → `bggrep` → `ctx_execute_file`.** +Reach for the sandbox only when you need something a regex over lines cannot +express — totals, dedup, grouping, joining the log against another file. + +`ctx_execute_file` is not itself a context dump: the file's bytes never enter +context, only your script's **stdout** does ("raw content never leaves"). So the +cost is exactly what you print — which makes `console.log(FILE_CONTENT)` (or +`print(open(path).read())`, or a big unbounded slice) the one way a whole-log +analysis turns into a context dump, and a capped-by-default 64 MiB log makes +that expensive rather than merely rude. Aggregate, then cap what you print: + +- print counts / grouped summaries / the first N matches — not the content; +- keep a `.slice(0, 40)` / `[:40]` on anything you echo; +- for many different questions about one big log, index it once (`ctx_index`) + and `ctx_search` it, instead of re-scanning the file per call; +- `bgtail` with a larger `lines`, or a tighter `bggrep` pattern, is usually the + cheaper answer to "I need to see more". + ## After a pi restart or session switch - The live wake does not survive a pi restart or a `/resume` to a different session @@ -116,6 +137,18 @@ Plain `grep` via bash is fine only for a one-off search you know is tiny. - Call the tools; never hand-roll `nohup … &` inline. - One job = one id. Multiple concurrent jobs are fine — each has its own log. +- Job logs are capped by default (`maxLogBytes` / `PI_BGRUN_MAX_LOG_BYTES`, + 64 MiB; `0` = unlimited) and the cap keeps the **first** bytes. A log that + ends with `[pi-bgrun] output truncated at bytes (first bytes kept)` + hit that ceiling: output past it was dropped, not lost to a failure — the job + still ran to completion with its real exit code, and readers (`bgtail`, + `bggrep`, the wake's line count/last line) filter the notice out. The wake's + Stats line, `bgtail` and `bggrep` all say when a log was capped (and report + `truncatedAtBytes` in their details), and a configured digest scorecard is + skipped rather than scored against an incomplete log — so on a capped job, + read a missing digest as "unknown", **not** as "no failures", and do not + re-run the command to see the missing tail; raise the ceiling if you need the + whole log. - Logs default to `/.pi-bgrun/jobs` in a repo (else `~/.pi-bgrun/jobs`; override with `PI_BGRUN_DIR` or `jobsDir`). Project-local dirs are auto-ignored via `.git/info/exclude`, which keeps `git status` clean; the From 311cd48c3996c31a61ac114448764e5b9d80186b Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 17:53:45 -0400 Subject: [PATCH 02/13] docs: deprecate the machine-global jobs dir; resolve home consistently MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Project-scoped logs are the model: one shared `~/.pi-bgrun/jobs` means cross-project clutter, ambiguous `bgstatus` scope, cleanup reaching into other projects' runs, and logs outside the workspace that project-sandboxed analysis tools would have to be handed by absolute path. Staged retirement, nothing breaks today: - `PI_BGRUN_GLOBAL_DIR` and the `~/.pi-bgrun/jobs` destination are marked deprecated in the env table, the Roadmap and the run-bg skill, with a dedicated section covering why, what is lost (cross-project discovery) and how to migrate. Removal is reserved for a future major. - An existing absolute `jobsDir` / `PI_BGRUN_DIR` keeps working exactly as before, and a cwd with no project root still falls back to the global dir — the alternative is scattering logs into an arbitrary cwd. Also resolves home through a HOME-first `homeDir()` helper (`process.env.HOME || homedir()`) for the global jobs dir, `~` expansion, the project-root exclusion and the user-config path. Node's os.homedir() already behaves this way; Bun's ignores HOME entirely, which is why the suite had to lean on PI_BGRUN_GLOBAL_DIR (and why resolveConfig carries a userConfigPath test seam). Tests now pin HOME, so retiring the deprecated knob will not require rewriting them. Green under both runners: bun and `node --test` (183/183 each). --- README.md | 38 +++++++++++++++++++++++++++++++++++++- extension/index.test.ts | 25 +++++++++++++++++-------- extension/index.ts | 25 +++++++++++++++++-------- skill/run-bg/SKILL.md | 5 +++-- 4 files changed, 74 insertions(+), 19 deletions(-) diff --git a/README.md b/README.md index fd39a4c..6c943cd 100644 --- a/README.md +++ b/README.md @@ -57,6 +57,7 @@ wake messages) is the agent's workflow. ## Roadmap / not provided +- Deprecated: the machine-global jobs dir (`PI_BGRUN_GLOBAL_DIR`, `~/.pi-bgrun/jobs`) — see [deprecation](#deprecated-machine-global-jobs-dir). Supported until a future major. - `bgkill` — not implemented; to stop a running job, use `kill -- -` (kill the process group — the child is spawned detached). The pid is the last `--`-separated segment of the job id (e.g. `unit-tests-1726680000-12345` → pid `12345`); it is not shown as a separate field in `bgstatus` output. - `bgwait` — not implemented; the wake mechanism makes blocking on a job unnecessary in the normal flow. @@ -244,12 +245,47 @@ Rules and migration notes: sweep and `bgclean all` both cover `~/.pi-bgrun/jobs` in addition to the current project's dir. +### Deprecated: machine-global jobs dir + +**Project-scoped logs are the model.** A single shared `~/.pi-bgrun/jobs` was +the old default; it is now **deprecated** and is no longer what any of the docs +lead with. Retirement is staged — nothing breaks today: + +- `PI_BGRUN_GLOBAL_DIR` and the `~/.pi-bgrun/jobs` **default are deprecated**; + they will be removed in a future major. +- **Supported for now:** an existing absolute `jobsDir` / `PI_BGRUN_DIR` keeps + working exactly as before, and a cwd with no project root still falls back to + `~/.pi-bgrun/jobs` (there is nowhere project-scoped to put it, and the + alternative — scattering logs into an arbitrary cwd — is worse). + +Why project-scoped won: + +- **Each checkout owns its logs** — no cross-project clutter, no ambiguous + `bgstatus` scope, and `bgclean` can't reach into another project's runs. +- **Reachable by project-sandboxed analysis** (`ctx_execute_file`, + `ctx_index`): logs live inside the workspace, so whole-log analysis no longer + needs a path outside it. +- **Disposable with the workspace** — delete the checkout, lose its logs. + +What changes for you, if you set a global dir on purpose: + +1. Drop the absolute `jobsDir` / `PI_BGRUN_DIR` from your config to get + `/.pi-bgrun/jobs`. +2. Planned sharing across projects is what you lose: jobs started in one + checkout are no longer visible to a session in another, and + `adoptForeignJobs` only adopts within the same jobs dir. If you need that, + keep the absolute dir — it is supported, merely no longer the recommended + default — and say so upstream if it is load-bearing for you. +3. Old logs in `~/.pi-bgrun/jobs` keep being swept (the orphan sweep and + `bgclean all` cover both dirs under the project-local default). Delete the + dir by hand once its logs are past retention. + Environment variables (same knobs, handy for one-off overrides): | Variable | Default | Description | | --- | --- | --- | | `PI_BGRUN_DIR` | `/.pi-bgrun/jobs` in repos; else `~/.pi-bgrun/jobs` | Override where job logs are stored. An absolute path is used as-is; a **relative** path resolves against the project root (see [project-local logs](#project-local-logs-default-in-repos)), falling back to `~/.pi-bgrun/jobs` when there is no project root. | -| `PI_BGRUN_GLOBAL_DIR` | `~/.pi-bgrun/jobs` | Override the machine-global jobs base — the no-project-root fallback. It is also swept under the project-local default (and is the `jobsDir` itself in the no-project-root fallback); an explicit absolute `jobsDir` is swept alone. A leading `~` or `~/` is expanded to the home dir; `~user` is not. | +| `PI_BGRUN_GLOBAL_DIR` | `~/.pi-bgrun/jobs` | **Deprecated.** Overrides the machine-global jobs base — the fallback used only when the cwd has no project root (see [deprecation](#deprecated-machine-global-jobs-dir)). A leading `~` or `~/` is expanded to the home dir; `~user` is not. | | `PI_BGRUN_FOREIGN_JOBS` | `false` | Adopt other sessions' running jobs into this session's widget and job list. Adopted jobs are polled so they leave the widget when they finish. | | `PI_BGRUN_SHOW_COMPLETED` | `false` | Include finished jobs in `bgstatus` listings by default. | | `PI_BGRUN_CLEANUP_DAYS` | `7` | Log retention for cleanup sweeps and the `bgclean` default. | diff --git a/extension/index.test.ts b/extension/index.test.ts index bd31a72..facbbfb 100644 --- a/extension/index.test.ts +++ b/extension/index.test.ts @@ -70,9 +70,18 @@ after(() => { }); // Isolate the machine-global jobs dir for the whole file so tests never read -// from or delete the real ~/.pi-bgrun/jobs. globalJobsDir() reads this per call. -const TEST_GLOBAL_JOBS_DIR = mkTmp("pi-bgrun-global-"); -process.env.PI_BGRUN_GLOBAL_DIR = TEST_GLOBAL_JOBS_DIR; +// from or delete the real ~/.pi-bgrun/jobs. A fake HOME is enough: the extension +// resolves home through its own HOME-first homeDir(), because Bun's +// os.homedir() ignores $HOME. PI_BGRUN_GLOBAL_DIR is left unset so a stray real +// one cannot point tests out of the sandbox. +// The extension resolves home HOME-first (Bun's os.homedir() ignores $HOME), so +// assertions must use the same rule production does — otherwise a suite that +// pins HOME compares against the developer's real home. +const homeDir = () => process.env.HOME || homedir(); +const TEST_FAKE_HOME = mkTmp("pi-bgrun-home-"); +process.env.HOME = TEST_FAKE_HOME; +delete process.env.PI_BGRUN_GLOBAL_DIR; +const TEST_GLOBAL_JOBS_DIR = join(TEST_FAKE_HOME, ".pi-bgrun", "jobs"); // Isolate the user config too: a real ~/.pi/agent/pi-bgrun.json could carry // adoptForeignJobs / digest / globalAutoClean settings that change results. @@ -2317,7 +2326,7 @@ test("resolveJobsDirPath: expands a leading ~ to the home dir (not project-local const scratch = mkTmp("pi-bgrun-scratch-"); try { const r = mod.resolveJobsDirPath("~/.pi-bgrun/jobs", { cwd: scratch }); - assert.equal(r.dir, join(homedir(), ".pi-bgrun", "jobs")); + assert.equal(r.dir, join(homeDir(), ".pi-bgrun", "jobs")); assert.equal(r.projectLocal, false); } finally { rmSync(scratch, { recursive: true, force: true }); @@ -2331,11 +2340,11 @@ test("resolveJobsDirPath: expands only a leading ~ (or ~/) — ~user and embedde mkdirSync(join(proj, ".git"), { recursive: true }); // Bare ~ → home dir (absolute, not project-local). const bare = mod.resolveJobsDirPath("~", { cwd: proj }); - assert.equal(bare.dir, homedir()); + assert.equal(bare.dir, homeDir()); assert.equal(bare.projectLocal, false); // ~/x → join(home, "x"). const sub = mod.resolveJobsDirPath("~/x", { cwd: proj }); - assert.equal(sub.dir, join(homedir(), "x")); + assert.equal(sub.dir, join(homeDir(), "x")); assert.equal(sub.projectLocal, false); // ~user/x is NOT expanded — treated as a relative path under the root. const user = mod.resolveJobsDirPath("~user/x", { cwd: proj }); @@ -2356,7 +2365,7 @@ test("resolveJobsDirPath: PI_BGRUN_GLOBAL_DIR is tilde-expanded", async () => { try { await withEnv("PI_BGRUN_GLOBAL_DIR", "~/.pi-bgrun/jobs", () => { const r = mod.resolveJobsDirPath(undefined, { cwd: scratch }); - assert.equal(r.dir, join(homedir(), ".pi-bgrun", "jobs")); + assert.equal(r.dir, join(homeDir(), ".pi-bgrun", "jobs")); assert.equal(r.projectLocal, false); }); } finally { @@ -2370,7 +2379,7 @@ test("resolveJobsDirPath: without PI_BGRUN_GLOBAL_DIR the global default is ~/.p try { await withEnv("PI_BGRUN_GLOBAL_DIR", undefined, () => { const r = mod.resolveJobsDirPath(undefined, { cwd: scratch }); - assert.equal(r.dir, join(homedir(), ".pi-bgrun", "jobs")); + assert.equal(r.dir, join(homeDir(), ".pi-bgrun", "jobs")); assert.equal(r.projectLocal, false); }); } finally { diff --git a/extension/index.ts b/extension/index.ts index 7e38716..42d2934 100644 --- a/extension/index.ts +++ b/extension/index.ts @@ -101,7 +101,7 @@ const STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".cnt"]; // ~/.pi-bgrun, and available for setups with a custom home or shared scratch. function globalJobsDir(): string { return expandTilde( - process.env.PI_BGRUN_GLOBAL_DIR || join(homedir(), ".pi-bgrun", "jobs"), + process.env.PI_BGRUN_GLOBAL_DIR || join(homeDir(), ".pi-bgrun", "jobs"), ); } @@ -703,7 +703,7 @@ function safeRealpath(p: string): string { // to $HOME. Paths are canonicalized so a symlinked $HOME is still recognized. function findProjectRoot( start: string, - home: string = homedir(), + home: string = homeDir(), ): string | undefined { const homeReal = safeRealpath(home); let cur = start; @@ -715,12 +715,20 @@ function findProjectRoot( } } +// The user's home directory, HOME-first. Node's os.homedir() already resolves +// HOME before falling back to the passwd entry, but Bun's ignores HOME — so +// deriving it here keeps `~`, the machine-global jobs dir and the project-root +// exclusion identical under both runtimes (and lets tests pin HOME). +function homeDir(): string { + return process.env.HOME || homedir(); +} + // Expand a leading `~` (bare or `~/...`) to the user's home directory so a // config/env path like `~/.pi-bgrun/jobs` is absolute rather than a relative // path interpreted project-locally. function expandTilde(p: string): string { - if (p === "~") return homedir(); - if (p.startsWith("~/")) return join(homedir(), p.slice(2)); + if (p === "~") return homeDir(); + if (p.startsWith("~/")) return join(homeDir(), p.slice(2)); return p; } @@ -1028,17 +1036,18 @@ function normalizeDigestEntry(raw: unknown): DigestEntry | undefined { export function resolveConfig(ctx?: { cwd?: string; isProjectTrusted?: () => boolean; - // Test seam: os.homedir() caches in some runtimes, so tests inject the user - // config path instead of mutating HOME. + // Test seam: an explicit path, immutable for the process. Tests may also + // simply pin HOME — homeDir() honors it under every runtime, unlike Bun's + // os.homedir(). userConfigPath?: string; }): BgrunConfig { // User config: $HOME/.pi/agent/pi-bgrun.json. Overridable by an explicit // test seam (ctx.userConfigPath) and by PI_BGRUN_USER_CONFIG (mirrors the - // PI_BGRUN_DIR escape hatch — mainly for tests, which cannot swap home). + // PI_BGRUN_DIR escape hatch). const user = readConfigFile( ctx?.userConfigPath ?? process.env.PI_BGRUN_USER_CONFIG ?? - join(homedir(), ".pi", "agent", "pi-bgrun.json"), + join(homeDir(), ".pi", "agent", "pi-bgrun.json"), ); let project: BgrunConfigFile = {}; try { diff --git a/skill/run-bg/SKILL.md b/skill/run-bg/SKILL.md index afced7f..5537235 100644 --- a/skill/run-bg/SKILL.md +++ b/skill/run-bg/SKILL.md @@ -149,8 +149,9 @@ that expensive rather than merely rude. Aggregate, then cap what you print: read a missing digest as "unknown", **not** as "no failures", and do not re-run the command to see the missing tail; raise the ceiling if you need the whole log. -- Logs default to `/.pi-bgrun/jobs` in a repo (else `~/.pi-bgrun/jobs`; - override with `PI_BGRUN_DIR` or `jobsDir`). Project-local dirs are +- Logs default to `/.pi-bgrun/jobs` in a repo — project-scoped is the + model (`~/.pi-bgrun/jobs` is a deprecated fallback for a cwd with no project + root; an absolute `PI_BGRUN_DIR`/`jobsDir` still works but is legacy). Project-local dirs are auto-ignored via `.git/info/exclude`, which keeps `git status` clean; the logs stay reachable for project-sandboxed analysis tools like `ctx_execute_file` because they live inside the project. From 1dcf365060a2303d45605861a768e760d109408d Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 17:53:50 -0400 Subject: [PATCH 03/13] ci: run everything on bun, drop the Node toolchain MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bun already ran every step: `bunx tsc` covers `npx tsc`, `npm test` just shells `bun test`, and `bun pm pack --dry-run` prints the same packed file list plus `Total files: N` that the tarball-allowlist guard needs (the guard's parse is re-pointed at Bun's casing). The setup-node step was installing a toolchain nothing used. What this gives up: the V8/worker_threads side of bggrep's bounded matching is no longer exercised in CI. Bun implements node:worker_threads, so the worker MECHANISM is still covered — only V8's backtracking behaviour is not. Insurance is a comment in the workflow: `node --test extension/index.test.ts` passes 183/183 in ~16s (Node 24.15); re-run it by hand after touching the worker path. --- .github/workflows/ci.yml | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index da91851..346da57 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -24,11 +24,11 @@ jobs: - name: Checkout uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 # v4.2.2 - - name: Set up Node 24 - uses: actions/setup-node@49933ea5288caeca8642d1e84afbd3f7d6820020 # v4.4.0 - with: - node-version: "24" - + # Bun-only on purpose: it runs every step below (lint, tests, pack + # listing), so a Node toolchain here would be dead weight. The one thing a + # Node job would add is the V8/worker_threads side of bggrep's bounded + # matching — verified by hand with `node --test extension/index.test.ts` + # (183 pass, ~16s). Re-run that by hand after touching the bggrep worker. - name: Set up Bun uses: oven-sh/setup-bun@v2 with: @@ -40,19 +40,19 @@ jobs: - name: tsc --noEmit id: tsc run: | - npx tsc --noEmit + bun run lint echo "result=passed" >> "$GITHUB_OUTPUT" - name: Run tests id: tests - run: npm test + run: bun test extension/index.test.ts - - name: npm pack --dry-run (files allowlist sanity) + - name: bun pm pack --dry-run (files allowlist sanity) id: pack run: | - pack_output=$(npm pack --dry-run 2>&1) + pack_output=$(bun pm pack --dry-run 2>&1) echo "$pack_output" - file_count=$(echo "$pack_output" | grep -oP 'total files:\s*\K[0-9]+' || echo "?") + file_count=$(echo "$pack_output" | grep -oP 'Total files:\s*\K[0-9]+' || echo "?") echo "file_count=${file_count}" >> "$GITHUB_OUTPUT" # Enforce the allowlist: test files and other non-runtime files must # never ship in the published tarball (they bloat installs and leak @@ -87,7 +87,7 @@ jobs: echo "|---|---|" echo "| tsc --noEmit | ${TSC_RESULT} |" echo "| tests | ${TESTS_OUTCOME} |" - echo "| npm pack --dry-run | ${PACK_OUTCOME} (${PACK_FILES} files in tarball) |" + echo "| bun pm pack --dry-run | ${PACK_OUTCOME} (${PACK_FILES} files in tarball) |" echo "" echo "Ref: \`${HEAD_SHA}\`" } > "$body_file" @@ -121,7 +121,7 @@ jobs: echo "|---|---|" echo "| tsc --noEmit | \`${TSC_RESULT}\` |" echo "| tests | \`${TESTS_OUTCOME}\` |" - echo "| npm pack --dry-run | \`${PACK_OUTCOME}\` — ${PACK_FILES} files in tarball |" + echo "| bun pm pack --dry-run | \`${PACK_OUTCOME}\` — ${PACK_FILES} files in tarball |" echo "" echo "Ref: \`${COMMIT_SHA}\`" } >> "$GITHUB_STEP_SUMMARY" From c2f4207c99b424435180e776f11649dc38573f39 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 18:01:57 -0400 Subject: [PATCH 04/13] test: verify the bggrep worker abort path, and fix a vacuous pathological test MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `bggrep: a pathological regex returns within the budget instead of hanging` never produced a pathological match. The log line was 60 000 "a"s plus a "b", but bggrep pre-truncates every line to BGGREP_LINE_CAP = 10 000 BEFORE matching, so the "b" that forces backtracking was cut away and `^(a+)+$` matched the remaining all-"a" line in 0ms on both engines. The failing character now sits inside the cap window, which makes the test real: on Node/V8 the same input spends the full 2s budget and requires the worker to be terminated (2004ms measured), while on Bun/JSC it answers in ~250ms. That split is the point: V8 backtracks exponentially where JSC does not — `^(a+)+$` over 100 "a"s + "!" hangs Node past 10s and returns on Bun in ~250ms — so an input-driven catastrophic pattern cannot assert the terminate() behaviour portably. matchLinesWithBudget() therefore takes an injectable worker body (defaulting to BGGREP_WORKER_SOURCE) and is exported for tests: a worker that never returns proves the budget still ends it, on any engine, in ~300ms. No behaviour change: the parameter is optional and only tests pass it. --- extension/index.test.ts | 38 ++++++++++++++++++++++++++++++++++---- extension/index.ts | 10 ++++++++-- 2 files changed, 42 insertions(+), 6 deletions(-) diff --git a/extension/index.test.ts b/extension/index.test.ts index facbbfb..8c1e4d4 100644 --- a/extension/index.test.ts +++ b/extension/index.test.ts @@ -5925,16 +5925,24 @@ test("bggrep: a pathological regex returns within the budget instead of hanging" const { pi, tools, ctx } = makeFakePi(); await loadExtension(pi); const id = `patho-${Math.floor(Date.now() / 1000)}-${process.pid}`; - // A long run of `a` then `b` is the classic catastrophic-backtracking input - // for `^(a+)+$`. Under Node/V8 this would lock the thread; the worker must - // abort at the 2s budget. Under Bun's engine it completes quickly. - writeFileSync(join(dir, `${id}.log`), "a".repeat(60_000) + "b\n"); + // Classic catastrophic-backtracking input for `^(a+)+$` — and the failing + // character has to sit INSIDE the per-line cap (BGGREP_LINE_CAP = 10 000), + // or the pre-match truncation removes it and the pattern matches instantly + // (measured: a 60 000-char line whose `!` lands past the cap matches in 0ms + // on BOTH engines, which made this test vacuous). + writeFileSync( + join(dir, `${id}.log`), + "a".repeat(9_000) + "!" + "a".repeat(50_000) + "\n", + ); const t0 = Date.now(); const res = await tools .get("bggrep")! .execute("c", { id, pattern: "^(a+)+$" }, undefined, undefined, ctx); const elapsed = Date.now() - t0; assert.ok(elapsed < 5_000, `bounded by the budget (${elapsed}ms)`); + // Engine-dependent by nature: V8 backtracks here and the budget must trip + // (see the abort-path test for that branch); JSC answers in ~250ms without + // backtracking. Both are acceptable — hanging is not. assert.ok( res.isError === true || typeof res.content[0].text === "string", "returns a result (no hang, no throw)", @@ -6700,3 +6708,25 @@ test("clampReadWindow: default, explicit, garbage, and ceiling", async () => { assert.equal(mod.clampReadWindow(65536.7), 65536); assert.equal(mod.clampReadWindow(1e12), 67108864); }); + +test("bggrep: the budget terminates a worker that is stuck mid-match (abort path)", async () => { + const mod: any = await loadModule(); + // An input-driven catastrophic pattern cannot test this portably: V8 + // backtracks exponentially where JSC answers in constant time (measured: + // `^(a+)+$` over 100 "a"s + "!" hangs Node past 10s and returns on Bun in + // ~250ms). So the stall is injected instead — a worker body that never + // returns — and the only assertion is that the budget still ends it. That is + // exactly what a runaway regex looks like to the parent thread. + const stall = 'require("node:worker_threads"); for (;;) {}'; + const t0 = Date.now(); + const outcome = await mod.matchLinesWithBudget( + "a", + ["a".repeat(50)], + 10, + 300, + stall, + ); + const elapsed = Date.now() - t0; + assert.equal(outcome.kind, "timeout", "a stuck worker is reported as a timeout"); + assert.ok(elapsed < 3_000, `terminated promptly (${elapsed}ms)`); +}); diff --git a/extension/index.ts b/extension/index.ts index 42d2934..3f61f03 100644 --- a/extension/index.ts +++ b/extension/index.ts @@ -181,11 +181,17 @@ function matchLinesSyncBounded( return { kind: "ok", matchIdx: out }; } -async function matchLinesWithBudget( +// Exported, and workerSource-injectable, so a test can prove the ABORT path on +// any engine: pass a worker body that never returns and the budget must still +// yield `{kind: "timeout"}`. Input-driven catastrophic patterns cannot test it +// — engines differ (V8 backtracks exponentially where JSC does not), so the +// only portable assertion is that termination works. +export async function matchLinesWithBudget( source: string, lines: string[], cap: number, budgetMs: number, + workerSource: string = BGGREP_WORKER_SOURCE, ): Promise { let WorkerCtor: typeof import("node:worker_threads").Worker; try { @@ -195,7 +201,7 @@ async function matchLinesWithBudget( } let worker: import("node:worker_threads").Worker; try { - worker = new WorkerCtor(BGGREP_WORKER_SOURCE, { + worker = new WorkerCtor(workerSource, { eval: true, workerData: { source, lines, cap }, }); From 63a1c15fb7c2e484063829b1e5a87029c86f858e Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 18:09:16 -0400 Subject: [PATCH 05/13] test: cover the bggrep sync fallback (the path without worker_threads) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit matchLinesSyncBounded runs only where node:worker_threads is unavailable — never on Node or Bun — so nothing exercised it: a regression there would ship silently and surface as "bggrep behaves differently in that environment", which is the worst way to find out. Exported for tests (like the other seams), and covered: - Parity with the worker path: same matchIdx for matches, misses, the per-line cap (a NEEDLE past cap 10 must be missed by both), and the same `invalid` outcome for a bad pattern. Parity is the contract — the fallback exists to degrade, not to disagree. - Both budget guards: fired before the first line when the budget is already spent, and re-checked mid-scan (a 0ms budget over 300 000 lines aborts instead of finishing the corpus). That guard is what keeps an unbounded scan off the main thread, which is the whole reason the worker exists. Suite: 186 pass / 0 fail under bun, and 186/186 under `node --test`. --- extension/index.test.ts | 55 +++++++++++++++++++++++++++++++++++++++++ extension/index.ts | 2 +- 2 files changed, 56 insertions(+), 1 deletion(-) diff --git a/extension/index.test.ts b/extension/index.test.ts index 8c1e4d4..2de9b5e 100644 --- a/extension/index.test.ts +++ b/extension/index.test.ts @@ -6730,3 +6730,58 @@ test("bggrep: the budget terminates a worker that is stuck mid-match (abort path assert.equal(outcome.kind, "timeout", "a stuck worker is reported as a timeout"); assert.ok(elapsed < 3_000, `terminated promptly (${elapsed}ms)`); }); + +// ── the sync fallback (bggrep without worker_threads) ────────────────────── +// +// Unreachable on Node and Bun, which is exactly why it needs direct tests: the +// path only runs where worker_threads is missing, so a regression would ship +// silently and surface as "bggrep behaves differently in that environment". + +test("bggrep sync fallback: same results as the worker path, including the line cap", async () => { + const mod: any = await loadModule(); + const lines = [ + "pass ok", + "--- FAIL: TestA", + "x".repeat(50) + "NEEDLE", // the only NEEDLE sits past the per-line cap + "--- FAIL: TestB", + "", + ]; + for (const pattern of ["^--- FAIL:", "NEEDLE", "^pass", "nothing-matches"]) { + const sync = mod.matchLinesSyncBounded(pattern, lines, 10, 1_000); + const worker = await mod.matchLinesWithBudget(pattern, lines, 10, 2_000); + assert.deepEqual( + sync, + worker, + `fallback and worker disagree for /${pattern}/`, + ); + if (pattern === "NEEDLE") { + assert.deepEqual(sync, { kind: "ok", matchIdx: [] }, "cap applies to both"); + } + } + // An invalid pattern must fail the same way on both paths. + assert.equal(mod.matchLinesSyncBounded("(", lines, 10, 1_000).kind, "invalid"); + assert.equal( + (await mod.matchLinesWithBudget("(", lines, 10, 2_000)).kind, + "invalid", + ); +}); + +test("bggrep sync fallback: a spent budget stops the scan before the first line", async () => { + const mod: any = await loadModule(); + // A negative budget is the deterministic spelling of "the clock says stop". + // If the guard did not fire up front, this fallback would happily scan an + // entire log on the main thread — the scenario the worker exists to avoid. + assert.equal( + mod.matchLinesSyncBounded("a", ["a", "a", "a"], 10, -1).kind, + "timeout", + ); + // And the mid-scan check: a budget spent while a real corpus is being scanned + // must abort too (the loop re-checks every 0x3ff lines). 300 000 lines of a + // simple pattern takes several ms, so a 0ms budget is provably exceeded. + const many = Array.from({ length: 300_000 }, (_, i) => `line ${i}`); + assert.equal( + mod.matchLinesSyncBounded("line", many, 100, 0).kind, + "timeout", + "a budget spent mid-scan aborts instead of finishing the corpus", + ); +}); diff --git a/extension/index.ts b/extension/index.ts index 3f61f03..b1375fc 100644 --- a/extension/index.ts +++ b/extension/index.ts @@ -157,7 +157,7 @@ type GrepMatchOutcome = // Bounded between lines only — a single pathological line can still stall. // Used solely when worker_threads is unavailable (never on Node or Bun). -function matchLinesSyncBounded( +export function matchLinesSyncBounded( source: string, lines: string[], cap: number, From f137a9fb1c35ddae97a92e554886fd4323c2beef Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 18:13:05 -0400 Subject: [PATCH 06/13] ci(release): document why publishing stays on npm, not bun publish MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit bun publish has no OIDC trusted-publishing or provenance support — it authenticates with a long-lived NPM_CONFIG_TOKEN — while this workflow relies on id-token: write and stores no token at all. Recorded next to the Node setup so a future 'make CI bun-only' sweep does not quietly downgrade the release path. --- .github/workflows/release.yml | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index d60b41c..dd33fbf 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -47,6 +47,11 @@ jobs: - name: Checkout uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 # v4.2.2 + # npm (Node) on purpose, unlike ci.yml which is bun-only: `bun publish` + # has no OIDC trusted-publishing or provenance support — it authenticates + # with a long-lived NPM_CONFIG_TOKEN — so switching would trade a + # tokenless, attested release for a stored bearer credential. Revisit only + # if Bun ships trusted publishing. - name: Set up Node 24 uses: actions/setup-node@49933ea5288caeca8642d1e84afbd3f7d6820020 # v4.4.0 with: From 8e27f03101b3ff5c3f59c4f1ad4ae7f978781640 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:27:34 -0400 Subject: [PATCH 07/13] fix: close the log-ceiling review defects (shell parsing, hang, bounds) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An adversarial pass over the committed ceiling (e7f0669, the `tee | head -c | cat` shape) reproduced eight defects. Each is now fixed and pinned by a test; with this test file run against e7f0669, 14 tests fail. - A ceiling literal `sh` cannot parse emptied the log: `1e21` reached the wrapper as `head -c 1e+21` (errors, writes nothing), and a fractional cap truncated to 0, which means unlimited — so the cap silently vanished. Normalize to an integer in 1..MAX_SAFE_INTEGER before it is interpolated. - A failed `mkfifo` ran uncapped *silently*: the fallback now prints a notice and sets the marker's `nocap` flag, so "ceiling unavailable" is not indistinguishable from "output was that small". - Truncation was inferable from printable text (a command echoing a notice-shaped line could fake a capped log). The state now comes from the writer: a fifo drain reports the byte budget, and the flag rides the exit marker's own line. - A backgrounded child held the job open: as a pipeline stage the wrapper waited for pipe EOF, so `sleep 30 & echo done` produced no wake for 30s — never, for a daemon. Completion now follows the command's pid, with a bounded drain grace. - The widest `bytes` window could not cover a capped log: it was clamped to the ceiling itself, which a capped log always exceeds. `readWindowMax()` is the ceiling plus the wrapper's overhead. - A window could be materialized line-by-line without bound (>3 GB of RSS for 64 MiB of one-character lines, i.e. an OOM on the log class the ceiling exists for). Bound to the last 500k lines, with a labelled note so a trimmed window is never reported as a plain "none" — and only report that note when the line limit actually trimmed bytes. - `countLogLines` scoped its scan bound to the cap, which would drop the line count for every capped job; it takes the tail offset from `fstatSync` and bounds the scan by the window bound instead. - Staging files outlived the sweep, while sweeping them on mtime alone would delete a running job's staged fifo. Sweep by mtime, skipping any stem whose `.pid` is a live process. --- extension/index.test.ts | 263 +++++++++++++++++++++-- extension/index.ts | 460 ++++++++++++++++++++++++++++++---------- 2 files changed, 590 insertions(+), 133 deletions(-) diff --git a/extension/index.test.ts b/extension/index.test.ts index 2de9b5e..bd82996 100644 --- a/extension/index.test.ts +++ b/extension/index.test.ts @@ -6080,14 +6080,19 @@ test("bgrun: maxLogBytes keeps the first N bytes, notes the truncation, preserve // The wrapped log fd is written by ONE writer at a time, so the notice // starts exactly at the cap: 1000 bytes of command output, then "\n". const noticeAt = log.indexOf( - "\n[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n", + "\n__BGRUN_TRUNC__ output truncated: kept the first 1000 bytes\n", ); assert.equal(noticeAt, 1000, "notice follows exactly the capped bytes"); assert.ok(log.startsWith("line-0-"), "the first bytes are kept"); assert.ok(!log.includes("line-199-"), "output past the cap was dropped"); - // Marker still last, and the real exit code survived the pipeline. + // Marker still last, carrying BOTH the real exit code and the truncation + // flag — the flag is what readers trust, since a command can print any + // notice text but only the last marker counts. const nonBlank = log.split("\n").filter((l) => l.trim().length > 0); - assert.equal(nonBlank[nonBlank.length - 1], "__BGRUN_EXIT__=3"); + assert.equal( + nonBlank[nonBlank.length - 1], + "__BGRUN_EXIT__=3 truncated=1000", + ); assert.match(wakes[0].text, /finished \(exit 3\)/); }); }); @@ -6115,7 +6120,7 @@ test("bgrun: the truncation notice is not job output — not counted, not the la assert.match(wakes[0].text, new RegExp(`, ${regionLines} lines`)); assert.match(wakes[0].text, /Last output: line-\d+-a+$/m); assert.ok( - !wakes[0].text.includes("Last output: [pi-bgrun]"), + !wakes[0].text.includes("Last output: __BGRUN_"), "the notice is never reported as the job's last line", ); }); @@ -6140,8 +6145,8 @@ test("bgrun: a job that outruns the cap by megabytes still finishes with its own await waitForWakes(wakes, 1); const log = readFileSync(join(dir, `${id}.log`), "utf8"); - assert.equal(log.indexOf("\n[pi-bgrun] output truncated"), 1000); - assert.match(log, /__BGRUN_EXIT__=0\n$/); + assert.equal(log.indexOf("\n__BGRUN_TRUNC__ output truncated"), 1000); + assert.match(log, /__BGRUN_EXIT__=0 truncated=1000\n$/); assert.match(wakes[0].text, /finished \(exit 0\)/); }); }); @@ -6175,10 +6180,11 @@ test("bgrun: a log at exactly the cap is not called truncated; one byte over is" const over = readFileSync(join(dir, `${overCap}.log`), "utf8"); assert.ok( over.includes( - "\n[pi-bgrun] output truncated at 4 bytes (first 4 bytes kept)\n", + "\n__BGRUN_TRUNC__ output truncated: kept the first 4 bytes\n", ), "one byte past the cap is truncated", ); + assert.match(over, /__BGRUN_EXIT__=0 truncated=4\n$/); assert.ok(over.startsWith("abcd"), "kept the first 4 bytes"); }); }); @@ -6219,7 +6225,7 @@ test("bgrun: a capped job leaves no staging files behind", async () => { ); await waitForWakes(wakes, 1); - // The exit-code file, the count fifo and the count file are the + // The exit-code, fifo, liveness and truncation-flag files are the // wrapper's own scratch — it removes them before printing the marker, so // a wake never leaves a `.tmp-*` in the jobs dir. const strays = readdirSync(dir).filter((n) => n.startsWith(".tmp-")); @@ -6228,7 +6234,7 @@ test("bgrun: a capped job leaves no staging files behind", async () => { }); }); -test("bgclean: stale staging files (.ec/.fifo/.cnt) are reclaimed, unrelated .tmp-* are not", async () => { +test("bgclean: stale staging files (.ec/.fifo/.pid/.trunc) are reclaimed, unrelated .tmp-* are not", async () => { const dir = mkdtempSync(join(tmpdir(), "pi-bgrun-test-")); process.env.PI_BGRUN_DIR = dir; try { @@ -6238,7 +6244,8 @@ test("bgclean: stale staging files (.ec/.fifo/.cnt) are reclaimed, unrelated .tm const ours = [ ".tmp-spew-1-abcd.ec", ".tmp-spew-1-abcd.fifo", - ".tmp-spew-1-abcd.cnt", + ".tmp-spew-1-abcd.pid", + ".tmp-spew-1-abcd.trunc", ".tmp-spew-1-abcd.log", ]; const foreign = ".tmp-someone-else.txt"; @@ -6368,28 +6375,50 @@ test("resolveConfig: maxLogBytes accepts 0 (unlimited) and ignores blank or inva // ── truncation is visible to the agent, not just on disk ─────────────────── -test("formatBytes / parseTruncationFromContent: the notice counts only as the wrapper's own line", async () => { +test("formatBytes / parseCapStatus: the cap comes from the marker, never from printable text", async () => { const mod = await loadModule(); assert.equal(mod.formatBytes(900), "900 bytes"); assert.equal(mod.formatBytes(1000), "1000 bytes"); assert.equal(mod.formatBytes(1536), "1.5 KiB"); assert.equal(mod.formatBytes(67108864), "64 MiB"); - // Real wrapper order: notice, then marker last. + // The wrapper's own marker, last, carries the flag. + assert.deepEqual( + mod.parseCapStatusFromContent( + "out\n\n__BGRUN_TRUNC__ output truncated: kept the first 1000 bytes\n\n__BGRUN_EXIT__=0 truncated=1000\n", + ), + { kind: "truncated", bytes: 1000 }, + ); assert.equal( - mod.parseTruncationFromContent("out\n\n[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n\n__BGRUN_EXIT__=0\n"), + mod.parseTruncationFromContent( + "out\n\n__BGRUN_TRUNC__ output truncated: kept the first 1000 bytes\n\n__BGRUN_EXIT__=0 truncated=1000\n", + ), 1000, ); - // A running log (no marker yet) and a command that merely PRINTS the phrase - // are not evidence of truncation. + // A ceiling that could not be installed is reported too, and is NOT a cap. + assert.deepEqual( + mod.parseCapStatusFromContent( + "out\n__BGRUN_NOCAP__ log ceiling unavailable (mkfifo failed, so this job ran uncapped)\n\n__BGRUN_EXIT__=0 nocap=1\n", + ), + { kind: "ceiling-failed" }, + ); + // A running log, a plain marker, and any printable imitation of the notice + // are not evidence of truncation. This is the direction that used to be + // forgeable: the notice used to be believed purely on position + text. assert.equal( - mod.parseTruncationFromContent("[pi-bgrun] output truncated at 1000 bytes (first 1000 bytes kept)\n"), + mod.parseTruncationFromContent( + "__BGRUN_TRUNC__ output truncated: kept the first 1000 bytes\n", + ), null, ); + assert.equal(mod.parseTruncationFromContent("boom\n__BGRUN_EXIT__=1\n"), null); assert.equal( - mod.parseTruncationFromContent("boom\n__BGRUN_EXIT__=1\n"), + mod.parseTruncationFromContent("x\n__BGRUN_TRUNC__ output truncated: kept the first 999 bytes\n\n__BGRUN_EXIT__=0\n"), null, + "a notice without the marker flag is not a cap", ); + assert.ok(mod.isWrapperLine("__BGRUN_TRUNC__ anything"), "namespace is reserved"); + assert.ok(!mod.isWrapperLine("[pi-bgrun] output truncated"), "old text is job output"); }); test("wake: a capped job says so in the Stats line; an uncapped one does not", async () => { @@ -6659,7 +6688,9 @@ test("bggrep/bgtail: `bytes` widens the search window without widening the outpu "output stays under the condenser cap", ); - // A window bigger than any job could write is clamped to the ceiling. + // A window bigger than any job could write is clamped to the bound in force + // — the ceiling plus the wrapper's overhead, so a capped log is coverable. + const mod = await loadModule(); const huge = await bggrep.execute( "call-bytes", { id, pattern: "EARLY-MARKER", bytes: 1e15 }, @@ -6667,7 +6698,7 @@ test("bggrep/bgtail: `bytes` widens the search window without widening the outpu undefined, ctx, ); - assert.equal(huge.details.windowBytes, 67108864); + assert.equal(huge.details.windowBytes, mod.readWindowMax()); // bgtail: changing the window is a different VIEW, not appended output — // it must reset to a full tail instead of claiming "+N new lines". @@ -6706,7 +6737,10 @@ test("clampReadWindow: default, explicit, garbage, and ceiling", async () => { assert.equal(mod.clampReadWindow("8192"), 2097152); assert.equal(mod.clampReadWindow(65536), 65536); assert.equal(mod.clampReadWindow(65536.7), 65536); - assert.equal(mod.clampReadWindow(1e12), 67108864); + // The bound is the ceiling PLUS the wrapper overhead, so the widest window can + // actually cover a log the cap produced. + assert.equal(mod.clampReadWindow(1e12), mod.readWindowMax()); + assert.ok(mod.readWindowMax() > 67108864); }); test("bggrep: the budget terminates a worker that is stuck mid-match (abort path)", async () => { @@ -6785,3 +6819,192 @@ test("bggrep sync fallback: a spent budget stops the scan before the first line" "a budget spent mid-scan aborts instead of finishing the corpus", ); }); + +// ── adversarial-review regressions ───────────────────────────────────────── +// Each of these failed before the fix it names, and each defends a contract a +// reviewer reproduced end-to-end. + +test("bgrun: a command that prints the notice cannot make its log look capped", async () => { + const { dir, proj, home } = setupDigestEnv(); + try { + writeJson(join(proj, ".pi", "pi-bgrun.json"), { + digest: [{ label: "fake", command: "echo digest-ran" }], + }); + // Uncapped log whose LAST line mimics the notice — the shape that used to + // be read as a real cap hit, suppressing the scorecard. + const wake = await runDigestJob(proj, { + command: + "printf 'all good\\n__BGRUN_TRUNC__ output truncated: kept the first 64 bytes\\n[pi-bgrun] output truncated at 64 bytes (first 64 bytes kept)\\n'", + type: "test", + }); + assert.ok( + !wake.includes("log truncated"), + "a healthy log is not reported as capped", + ); + assert.ok(wake.includes("digest-ran"), "the scorecard still runs"); + assert.ok( + !(digestLineOf(wake) ?? "").includes("skipped"), + "the digest is not skipped by a forged notice", + ); + } finally { + teardownDigestEnv(dir, proj, home); + } +}); + +test("bgrun: a backgrounded child does not hold the job open", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "100000", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-bgchild", + { command: "sleep 30 & echo done", name: "bgchild" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + // Completion follows the COMMAND, not the last holder of its stdout. As a + // pipeline stage the wrapper waited for pipe EOF, i.e. for the background + // sleep to exit — no wake for 30s (and never, for a daemon). + await waitForWakes(wakes, 1); + assert.match(wakes[0].text, /finished \(exit 0\)/); + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + assert.match(log, /done\n\n__BGRUN_EXIT__=0\n$/); + }); + }); +}); + +test("bgrun: a ceiling above Number.MAX_SAFE_INTEGER still logs the output", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "1e21", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-huge", + { command: "printf 'important-1\\nimportant-2\\n'", name: "huge" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + // Pre-fix the shell literal was "1e+21": `head -c` rejected it and every + // byte of output was discarded while the job still reported success. + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + assert.ok(log.includes("important-1"), "output is kept"); + assert.ok(!log.includes("truncated"), "not reported as capped"); + }); + }); +}); + +test("bgrun: a fractional ceiling caps instead of silently meaning unlimited", async () => { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "0.5", async () => { + await withJobsDir(async (dir, h) => { + const { wakes, tools, ctx } = h; + const res = await tools.get("bgrun")!.execute( + "call-cap-fraction", + { command: "printf 'abcdefghij'", name: "frac" }, + undefined, + undefined, + ctx, + ); + const id = startedId(res); + await waitForWakes(wakes, 1); + // 0.5 floors to 0, and 0 is documented as unlimited — the cap the user + // asked for would be silently off. It must mean "one byte" instead. + const log = readFileSync(join(dir, `${id}.log`), "utf8"); + assert.ok(log.startsWith("a\n"), `kept one byte: ${JSON.stringify(log)}`); + assert.match(log, /__BGRUN_EXIT__=0 truncated=1\n$/); + }); + }); +}); + +test("readWindowMax: the widest search window can cover a log the ceiling produced", async () => { + const mod = await loadModule(); + for (const cap of ["1048576", "67108864", "134217728"]) { + await withEnv("PI_BGRUN_MAX_LOG_BYTES", cap, async () => { + // A capped log is cap + notice + marker, so a max EQUAL to the cap left + // its first bytes permanently unreadable through bgtail/bggrep. + assert.ok( + mod.readWindowMax() > Number(cap), + `window max must exceed the ceiling in force (${cap})`, + ); + }); + } + await withEnv("PI_BGRUN_MAX_LOG_BYTES", "0", async () => { + assert.ok(mod.readWindowMax() > 67108864, "unlimited keeps a usable bound"); + }); +}); + +test("bgtail/bggrep: a window of very short lines is scan-bounded, and says so", async () => { + await withJobsDir(async (dir, h) => { + // 250k single-character lines: well under the byte window, but the shape a + // capped `yes ''` runaway produces — materializing every line costs GBs. + const id = "shortlines-1-1"; + const body = Array.from({ length: 600_000 }, (_, i) => + i === 0 ? "FIRST-MARKER" : "x", + ).join("\n"); + writeFileSync(join(dir, `${id}.log`), `${body}\n\n__BGRUN_EXIT__=0\n`); + + const grep = await h.tools + .get("bggrep")! + .execute("c", { id, pattern: "FIRST-MARKER" }, undefined, undefined, h.ctx); + const text = grep.content[0].text as string; + assert.match(text, /only the last [\d,]+ lines of that window were searched/); + assert.match(text, /none/, "the trimmed-away head is not silently searched"); + + const tail = await h.tools + .get("bgtail")! + .execute("c2", { id, lines: 3 }, undefined, undefined, h.ctx); + assert.match( + tail.content[0].text as string, + /only the last [\d,]+ lines/, + "bgtail reports the same bound", + ); + }); +}); + +test("bgclean: a running job's staging files survive an aggressive sweep", async () => { + const dir = mkdtempSync(join(tmpdir(), "pi-bgrun-test-")); + process.env.PI_BGRUN_DIR = dir; + markJobsDir(dir); + try { + const stale = new Date(Date.now() - 30 * 24 * 60 * 60 * 1000); + const live = ".tmp-live-1-beef"; + const orphan = ".tmp-dead-1-beef"; + // A live owner (this process) and an ownerless leftover, both as old as the + // cutoff. Age alone used to delete the live job's scratch files mid-run, + // which silently removed its truncation notice and injected a shell error + // into its log. + for (const name of [`${live}.pid`, `${live}.fifo`, `${live}.trunc`, `${orphan}.fifo`]) { + writeFileSync(join(dir, name), ""); + utimesSync(join(dir, name), stale, stale); + } + // Written after the loop: this is the file the sweep trusts for liveness. + writeFileSync(join(dir, `${live}.pid`), `${process.pid}\n`); + utimesSync(join(dir, `${live}.pid`), stale, stale); + + const { pi, tools, ctx } = makeFakePi(); + await loadExtension(pi); + await tools + .get("bgclean")! + .execute( + "call-cap-live-sweep", + { days: 0.0000001, all: true }, + undefined, + undefined, + ctx, + ); + + assert.ok( + existsSync(join(dir, `${live}.fifo`)), + "a running job keeps its staging files", + ); + assert.ok( + !existsSync(join(dir, `${orphan}.fifo`)), + "an orphan's staging files are still reclaimed", + ); + } finally { + delete process.env.PI_BGRUN_DIR; + rmSync(dir, { recursive: true, force: true }); + } +}); diff --git a/extension/index.ts b/extension/index.ts index b1375fc..1de3644 100644 --- a/extension/index.ts +++ b/extension/index.ts @@ -74,16 +74,39 @@ const BGGREP_LINE_CAP = 10_000; // per-line match length cap // Cap on the bytes a job may write to its log (stdout+stderr). Enforced inside // the detached process tree, so it holds after pi exits. 0 = unlimited. const DEFAULT_MAX_LOG_BYTES = 64 * 1024 * 1024; -// Upper bound for an explicit search window (bgtail/bggrep `bytes`). A job can -// never have written more than the ceiling, and the window is scanned in-process -// (bggrep ships the lines to a worker), so widening it costs CPU and memory — but -// NOT context: the returned text stays capped by the condenser (~8 KB). -const LOG_READ_BYTES_MAX = DEFAULT_MAX_LOG_BYTES; -// The wrapper appends this line (with a leading newline) when it had to drop -// output. Readers filter it exactly like EXIT_MARKER: wrapper bookkeeping, not -// job output, so it must not be counted as a content line or reported as the -// job's last line. -const TRUNC_NOTICE_PREFIX = "[pi-bgrun] output truncated"; +// Above 2^53-1 a Number stringifies in exponential notation ("1e+21"), and the +// wrapper bakes the ceiling into the shell as a literal — `head -c 1e+21` fails +// and every byte of job output is discarded. A ceiling that large means +// "effectively unlimited", so it is clamped to the largest integral literal the +// shell can still parse. +const MAX_MAX_LOG_BYTES = Number.MAX_SAFE_INTEGER; +// Slack added when deriving read/count bounds from a ceiling: the wrapper writes +// its notice and exit marker PAST the capped bytes, so a capped log is slightly +// larger than the cap. A bound equal to the cap leaves the first bytes of every +// capped log unreadable and drops its line count. +const WRAPPER_OVERHEAD_BYTES = 4096; +// Machine-readable flags the wrapper appends to its exit marker. The marker is +// the one line a command cannot forge (only the LAST marker counts, so printing +// one is not evidence of completion) — carrying truncation there makes "the log +// was capped" unforgeable, unlike a printable notice line that job output can +// imitate. +const EXIT_MARKER_TRUNC_FLAG = " truncated="; +const EXIT_MARKER_NOCAP_FLAG = " nocap=1"; +// Human-readable wrapper notices, in the reserved `__BGRUN_` namespace so they +// cannot collide with a command's own output. Readers filter them exactly like +// EXIT_MARKER: wrapper bookkeeping, not job output, so they are never counted as +// content lines or reported as the job's last line. +const TRUNC_NOTICE_PREFIX = "__BGRUN_TRUNC__ output truncated"; +const CAPFAIL_NOTICE_PREFIX = "__BGRUN_NOCAP__ log ceiling unavailable"; +// Line bound for a log scan. A byte window alone is not enough: a capped log of +// very short lines (the classic `yes ''` runaway) holds millions of lines in a +// few MiB, and materializing them as JS strings costs ~100 bytes each — measured +// at >3 GB of RSS for a 64 MiB window, i.e. an OOM on exactly the log class the +// ceiling exists for. 500k lines is ~40 MB of JS strings — a bounded cost that +// still dwarfs anything a real job prints into a window. +// ceiling exists for. Past this many lines only the tail is scanned, and the +// caveat says so. +const LOG_SCAN_LINES_MAX = 500_000; const DEFAULT_CLEANUP_DAYS = 7; const STALE_POLL_MS = 30_000; // re-check interval for jobs with no live child handle @@ -92,9 +115,16 @@ const PROJECT_LOCAL_JOBS_REL = ".pi-bgrun/jobs"; // Files a spawn stages in the jobs dir under one shared // `.tmp---` stem: the log itself (renamed to `.log` once the -// child pid is known) plus the wrapper's exit-code, fifo and byte-count files. -// Only these exact suffixes are ours — an unrelated `.tmp-*` is not. -const STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".cnt"]; +// child pid is known) plus the wrapper's exit-code, fifo, liveness and +// truncation-flag files. Only these exact suffixes are ours — an unrelated +// `.tmp-*` is not. +const STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".pid", ".trunc"]; +// A staging file is only reclaimable once it is clearly nobody's business: the +// owner's liveness file says the wrapper is gone AND the file is older than this +// floor. Without the floor, an aggressive cleanup cutoff (a `bgclean` "clean +// everything" using a tiny positive `days`) can unlink the scratch files of a +// job that started milliseconds ago, before its liveness file exists. +const STAGING_MIN_AGE_MS = 60_000; // Machine-global jobs dir. Resolved per call (not a module constant) so // PI_BGRUN_GLOBAL_DIR can redirect it — used by tests to stay off the real @@ -133,14 +163,69 @@ try { } `; +// Normalize a configured byte ceiling. 0 stays "unlimited"; a positive fraction +// (0.5) becomes 1 rather than flooring to 0, which would silently mean +// "unlimited"; anything above MAX_MAX_LOG_BYTES is clamped so the value always +// renders as a plain integer in the wrapper. +export function normalizeMaxLogBytes(value: unknown): number | undefined { + if (typeof value !== "number" || !Number.isFinite(value) || value < 0) { + return undefined; + } + if (value === 0) return 0; + const floored = Math.floor(value); + if (floored < 1) return 1; + return Math.min(floored, MAX_MAX_LOG_BYTES); +} + +// Upper bound for an explicit search window (bgtail/bggrep `bytes`): the ceiling +// in force plus the wrapper's overhead, so the widest window a caller can ask +// for can actually cover a log the cap produced. An equal-to-cap bound (the +// original constant) left the first bytes of every capped log unreadable while +// the caveat advertised itself as the remedy. +export function readWindowMax(): number { + let cap = DEFAULT_MAX_LOG_BYTES; + try { + const configured = resolveConfig().maxLogBytes; + if (configured > 0) cap = configured; + } catch { + // No resolvable config → the default ceiling. + } + return cap + WRAPPER_OVERHEAD_BYTES; +} + // Clamp a caller-supplied log search window: absent/garbage/non-positive → -// the default, anything wider than the ceiling → the ceiling (searching past -// what a job could have written is pure cost). -export function clampReadWindow(bytes: unknown): number { +// the default, anything wider than the bound above → the bound (searching past +// what a job could have written is pure cost, and the window is materialized). +export function clampReadWindow(bytes: unknown, max = readWindowMax()): number { if (typeof bytes !== "number" || !Number.isFinite(bytes) || bytes <= 0) { return LOG_READ_BYTES; } - return Math.min(Math.floor(bytes), LOG_READ_BYTES_MAX); + return Math.min(Math.floor(bytes), max); +} + +// Trim a scan window to its last LOG_SCAN_LINES_MAX lines without splitting the +// whole window first: walking the newline positions backwards costs one pass +// over the window and never materializes millions of short strings. Returns the +// text to scan plus whether the line bound (rather than the byte window) decided +// the view, so callers can say so instead of implying the whole window was read. +export function boundScanLines(content: string): { + content: string; + lineBoundHit: boolean; +} { + let end = content.length; + let seen = 0; + while (seen < LOG_SCAN_LINES_MAX) { + const nl = content.lastIndexOf("\n", end - 1); + if (nl === -1) break; + end = nl; + seen++; + } + // "Hit" only when the limit is what stopped the walk AND bytes were actually + // trimmed off the front — running out of newlines means the whole window fits. + const hit = seen === LOG_SCAN_LINES_MAX && end > 0; + return hit + ? { content: content.slice(end + 1), lineBoundHit: true } + : { content, lineBoundHit: false }; } // Read at call time so tests (and users) can lower the budget; a non-positive @@ -309,35 +394,50 @@ export function parseExitFromLogPath(logPath: string): number | null { // Wrapper bookkeeping lines — never job output. Every reader filters them, so a // capped log's last line, line count, tail window and grep results still // describe the COMMAND's output rather than the wrapper's own bookkeeping. +// The whole `__BGRUN_` namespace is reserved (exit marker + notices), which is +// also what makes a command printing those lines a deliberate forgery rather +// than an accident. export function isWrapperLine(line: string): boolean { - return ( - line.startsWith(EXIT_MARKER) || line.startsWith(TRUNC_NOTICE_PREFIX) - ); + return line.startsWith("__BGRUN_"); } -// The byte ceiling a log actually hit, or null when it was not capped. Exact by -// construction: the notice only counts when it is the line immediately before -// the exit marker, which is the order the wrapper writes them in (marker last). -// A command that merely prints the phrase is not evidence of truncation. -export function parseTruncationFromContent(content: string): number | null { +// What the wrapper recorded about the ceiling, read from the exit marker — the +// last non-empty line, and the only line a command cannot forge: only the LAST +// marker counts, so printing one is not evidence of completion. The flag rides +// on that marker ("__BGRUN_EXIT__=0 truncated=1000"), which is why a command's +// own output can no longer make a healthy log look capped (it used to be read +// from the notice line, whose position and text a command controls). +export type CapStatus = + | { kind: "truncated"; bytes: number } + | { kind: "ceiling-failed" } + | null; + +export function parseCapStatusFromContent(content: string): CapStatus { const lines = content.split("\n"); let i = lines.length - 1; while (i >= 0 && lines[i].trim().length === 0) i--; - if (i < 0 || !lines[i].startsWith(EXIT_MARKER)) return null; - i--; - while (i >= 0 && lines[i].trim().length === 0) i--; - if (i < 0 || !lines[i].startsWith(TRUNC_NOTICE_PREFIX)) return null; - const match = lines[i].match(/ at (\d+) bytes \(first /); - return match ? parseInt(match[1], 10) : null; + if (i < 0) return null; + const marker = lines[i]; + if (!marker.startsWith(EXIT_MARKER)) return null; + const truncated = marker.match(/ truncated=(\d+)/); + if (truncated) return { kind: "truncated", bytes: parseInt(truncated[1], 10) }; + if (marker.includes(EXIT_MARKER_NOCAP_FLAG)) return { kind: "ceiling-failed" }; + return null; +} + +// The byte ceiling a log hit, or null when it was not capped. Thin accessor over +// the marker parse, kept because most callers only care about the number. +export function parseTruncationFromContent(content: string): number | null { + const status = parseCapStatusFromContent(content); + return status?.kind === "truncated" ? status.bytes : null; } -// The notice is written within the last few hundred bytes of the log (it -// precedes the exit marker), so the standard tail slice decides it — no full -// read, even for a log at the ceiling. -function readTruncationBytes(logPath: string): number | null { +// The marker is written within the last few hundred bytes of the log, so the +// standard tail slice decides this — no full read, even at the ceiling. +function readCapStatus(logPath: string): CapStatus { const slice = readLogSlice(logPath, LOG_TAIL_BYTES); if (!slice) return null; - return parseTruncationFromContent(slice.content); + return parseCapStatusFromContent(slice.content); } // Compact byte size for the wake and reader notes ("64 MiB", "1.5 KiB", @@ -629,48 +729,119 @@ function readConfigFile(path: string): BgrunConfigFile { return {}; } +// A byte-budget copier that writes as it reads: keep the first $cap bytes of +// stdin on stdout, flag (O_EXCL, 0600) if anything was left over, and drain the +// rest so the producer never gets SIGPIPE. Used as the drain when perl is +// available: `dd` and `head` are the portable choices, but both buffer their +// output — measured: nothing on disk until 4-8 KiB accumulated, so a running +// capped job's log looks stalled for a slow producer, breaking the live-tail +// workflow bgtail documents. perl's sysread/syswrite has no stdio buffering, so +// the first byte lands immediately. The program avoids quotes so it can be +// single-quoted in the wrapper. +const PERL_CAP_COPIER = [ + `use Fcntl;`, + `my $cap = $ARGV[0]; my $flag = $ARGV[1]; my $left = $cap; my $over = 0; my $flagged = 0; my $buf;`, + `while (1) {`, + ` my $n = sysread(STDIN, $buf, 65536);`, + ` last if !defined($n) || $n == 0;`, + ` if ($left > 0) {`, + ` my $take = $n < $left ? $n : $left;`, + ` my $off = 0;`, + ` while ($off < $take) { my $w = syswrite(STDOUT, $buf, $take - $off, $off); last if !defined($w) || $w <= 0; $off += $w; }`, + ` $left -= $off;`, + ` $over = 1 if $n > $take;`, + ` } else { $over = 1; }`, + ` if ($over && !$flagged) { my $fh; if (sysopen($fh, $flag, O_WRONLY | O_CREAT | O_EXCL, 0600)) { close($fh); } $flagged = 1; }`, + `}`, +].join("\n"); + // ── Job wrapper ───────────────────────────────────────────────────────────── // // Every job runs inside a detached `sh -c` tree, so the log ceiling has to live // there too — it must hold after pi exits. The command is passed as argv ($1), // never interpolated, or `#`, quotes and heredocs would break. // -// Capped shape: the command's output is tee'd into a byte counter and piped -// through `head -c` into the log, with `cat >/dev/null` draining the rest so the -// producer never gets SIGPIPE — the job runs to completion and keeps its real -// exit code. That code travels through a file, not the pipe, because a -// pipeline's `$?` is the reader's. +// Capped shape: the command runs as its OWN background job writing into a fifo; +// a drain copies at most `cap` bytes of that into the log and then reports +// whether anything was left over. Two properties drive that structure: // -// Why the count comes from a tee'd copy instead of "what head left behind": -// `head -c` reads into a buffer and discards the excess, so the remainder -// under-reports (measured on macOS: a 1500-byte stream capped at 1000 leaves 0, -// not 500). Sizing the log fd directly is no better — it is opened O_WRONLY, so -// reopening /dev/fd/1 fails with EACCES. `wc -c` on an uncapped copy is exact. +// - Completion must follow the COMMAND, not the data flow. As a pipeline stage, +// `wait` would return only when every holder of the pipe's write end closes +// it — and a child the command backgrounded (`server &`, a watcher, a +// daemonized tool) inherited that fd, so the job would never wake while the +// child lived. `wait "$prod"` returns when `sh -c` is reaped; the strays keep +// running, they just stop being logged (which is the point of a ceiling). +// - The drain may outlive the command, so truncation is reported through a flag +// FILE, and the wrapper's exit marker carries the machine-readable flag. A +// notice line in the log is not evidence: a command can print the same text, +// and only the LAST marker counts, so the marker is the one line a command +// cannot forge. // -// If `mkfifo` fails, fall back to the uncapped path: losing output is worse -// than losing the ceiling. +// The drain's byte budget is exact only with `dd iflag=fullblock` (each block is +// filled before it counts): plain `dd` counts READS, so a slow writer would +// exhaust the budget without filling the cap. Without `iflag` (most non-GNU +// systems) `head -c` is used instead — exact, but block-buffered, so a running +// job's log lags by up to 8 KiB until the job exits. // -// argv: $1 command, $2 ecfile, $3 fifo, $4 countfile. +// If `mkfifo` fails, fall back to the uncapped path: losing output is worse than +// losing the ceiling — but say so, in the log and in the marker. +// +// argv: $1 command, $2 ecfile, $3 fifo, $4 pidfile, $5 truncation flag. export function cappedWrapper(maxBytes: number): string { const cap = String(maxBytes); return [ - `if mkfifo "$3" 2>/dev/null; then`, - ` rm -f "$4"; ( wc -c <"$3" >"$4" ) & ctr=$!`, - ` { sh -c "$1" 2>&1; ec=$?; printf '%d' "$ec" >"$2"; } | tee "$3" | { head -c ${cap}; cat >/dev/null; }`, - ` wait "$ctr"`, - ` total=$(tr -d '[:space:]' <"$4" 2>/dev/null)`, - ` rm -f "$3" "$4"`, - ` if [ "\${total:-0}" -gt ${cap} ]; then`, - ` printf '\\n${TRUNC_NOTICE_PREFIX} at %s bytes (first %s bytes kept)\\n' ${cap} ${cap}`, + `flag=`, + // Staging names are ours: clear any leftover or planted entry first — rm + // unlinks the name and never follows a link — and every write below runs + // under `set -C` (noclobber) so a path that reappears is refused rather than + // written through. umask is scoped to those writes: the command must keep + // its own. + `rm -f "$2" "$3" "$4" "$5" 2>/dev/null`, + `if mkfifo -m 600 "$3" 2>/dev/null && [ -p "$3" ]; then`, + ` ( umask 077; set -C; printf '%d' "$$" >"$4" ) 2>/dev/null || :`, + ` { sh -c "$1" 2>&1; ec=$?; ( umask 077; set -C; printf '%d' "$ec" >"$2" ) 2>/dev/null; } >"$3" &`, + ` prod=$!`, + ` { if command -v perl >/dev/null 2>&1; then`, + // One process: cap + flag + drain, no stdio buffering (see PERL_CAP_COPIER). + ` perl -e '${PERL_CAP_COPIER}' ${cap} "$5"`, + ` elif dd iflag=fullblock bs=1 count=0 /dev/null 2>&1; then`, + // Exact, but block-buffered: the log lags by up to one block while the job + // runs. (Plain `dd` is worse: it counts READS, so a slow writer exhausts the + // budget without filling the cap and later output is dropped.) + ` { dd iflag=fullblock bs=4096 count=$(( ${cap} / 4096 )) 2>/dev/null; dd iflag=fullblock bs=1 count=$(( ${cap} % 4096 )) 2>/dev/null; }`, + ` if [ "$(dd bs=1 count=1 2>/dev/null | wc -c)" -gt 0 ]; then ( umask 077; set -C; : >"$5" ) 2>/dev/null || :; fi`, + ` cat >/dev/null`, + ` else`, + ` head -c ${cap}`, + ` if [ "$(dd bs=1 count=1 2>/dev/null | wc -c)" -gt 0 ]; then ( umask 077; set -C; : >"$5" ) 2>/dev/null || :; fi`, + ` cat >/dev/null`, + ` fi; } <"$3" &`, + ` drain=$!`, + ` wait "$prod"`, + // The command is done. The drain copies unbuffered, so there is nothing to + // flush — this short bounded wait only gives it the moment it needs to + // notice EOF. A child the command backgrounded and did not wait for can hold + // the fifo open indefinitely; the job must complete anyway (and that stray's + // output simply stops being logged, which is what a ceiling is for). Note + // that after the byte budget is spent only the discard stage remains, so + // nothing can be written to the log after these notices. + ` j=0`, + ` while kill -0 "$drain" 2>/dev/null && [ "$j" -lt 5 ]; do sleep 0.02; j=$((j + 1)); done`, + ` ec=$(if [ -f "$2" ]; then cat "$2" 2>/dev/null; fi)`, + ` if [ -e "$5" ]; then`, + ` printf '\\n${TRUNC_NOTICE_PREFIX}: kept the first %s bytes\\n' ${cap}`, + ` flag="${EXIT_MARKER_TRUNC_FLAG}${cap}"`, ` fi`, - ` ec=$(cat "$2" 2>/dev/null)`, `else`, ` sh -c "$1" 2>&1`, ` ec=$?`, + ` printf '\\n${CAPFAIL_NOTICE_PREFIX} (mkfifo failed, so this job ran uncapped)\\n'`, + ` flag="${EXIT_MARKER_NOCAP_FLAG}"`, `fi`, - `rm -f "$2"`, + `rm -f "$2" "$3" "$4" "$5" 2>/dev/null`, `[ -n "$ec" ] || ec=-1`, - `printf '\\n${EXIT_MARKER}%d\\n' "$ec"; exit "$ec"`, + `printf '\\n%s%d%s\\n' "${EXIT_MARKER}" "$ec" "\${flag}"`, + `exit "$ec"`, ].join("\n"); } @@ -1096,22 +1267,18 @@ export function resolveConfig(ctx?: { const daysEnv = Number.isFinite(envDays) && envDays > 0 ? envDays : undefined; // Byte ceiling: unlike cleanupDays, 0 is meaningful ("unlimited"), so it is // accepted — but a BLANK env var is not, or an empty - // PI_BGRUN_MAX_LOG_BYTES= would silently disable the cap. - const maxBytesFile = - typeof merged.maxLogBytes === "number" && - Number.isFinite(merged.maxLogBytes) && - merged.maxLogBytes >= 0 - ? Math.floor(merged.maxLogBytes) - : undefined; + // PI_BGRUN_MAX_LOG_BYTES= would silently disable the cap. Normalization also + // keeps the value in a range the wrapper can express: a positive fraction + // becomes 1 (flooring it to 0 would silently mean "unlimited"), and an + // enormous value is clamped instead of stringifying to "1e+21", which the + // shell's `head -c`/`dd` reject — discarding every byte of job output. + const maxBytesFile = normalizeMaxLogBytes(merged.maxLogBytes); const maxBytesRaw = process.env.PI_BGRUN_MAX_LOG_BYTES; const maxBytesEnvValue = maxBytesRaw === undefined || maxBytesRaw.trim() === "" ? NaN : Number(maxBytesRaw); - const maxBytesEnv = - Number.isFinite(maxBytesEnvValue) && maxBytesEnvValue >= 0 - ? Math.floor(maxBytesEnvValue) - : undefined; + const maxBytesEnv = normalizeMaxLogBytes(maxBytesEnvValue); const { dir: jobsDir, projectLocal: jobsDirProjectLocal } = resolveJobsDirPath(process.env.PI_BGRUN_DIR || dirFile, ctx); // Digest section: accept either the legacy single-object form (normalized to @@ -1302,12 +1469,6 @@ export default function (pi: ExtensionAPI) { return normalizeType(type); } - // Hard read bound for the line-count scan. The ceiling normally keeps logs - // small, but `maxLogBytes: 0` (unlimited) and logs from a run with a higher - // ceiling still reach here, and this runs on the main thread at every job - // exit. Past the bound the count is omitted rather than reported wrong. - const COUNT_SCAN_MAX_BYTES = 64 * 1024 * 1024; - // Count the log's total lines with a bounded-memory streaming scan (one // fixed-size buffer, no full-file read). Missing/unreadable file → null: // the Stats line then just omits the line count — best-effort, never @@ -1324,7 +1485,10 @@ export default function (pi: ExtensionAPI) { // by the REAL file size, so bounding the scan can never misplace it. const size = fstatSync(fd).size; if (size === 0) return 0; - if (size > COUNT_SCAN_MAX_BYTES) return null; + // readWindowMax, not the cap: a capped log is cap + notice + marker, so a + // bound EQUAL to the cap would omit the line count for every capped job — + // exactly where magnitude matters most. + if (size > readWindowMax()) return null; const buf = Buffer.alloc(64 * 1024); let newlines = 0; let seen = 0; @@ -1347,17 +1511,31 @@ export default function (pi: ExtensionAPI) { const tailText = tail.toString("latin1"); const endsWithNewline = tailText.charCodeAt(tailText.length - 1) === 0x0a; let count = newlines + (endsWithNewline ? 0 : 1); - // The wrapper appends "\n\n" — and, when it had to drop - // output, "\n\n" before that. Those newlines are not command - // output. Drop the whole trailing wrapper block, including its leading - // separator when the output already ended in a newline. + // The wrapper appends "\n\n" — and, when it had to + // drop output or could not install the ceiling, "\n\n" before + // that. Those newlines are not command output, so drop the whole trailing + // wrapper block, including its leading separator when the output already + // ended in a newline. WHICH notice precedes the marker is decided by the + // marker's own flags, not by matching notice text: a command that prints + // the phrase must not have its line discounted as wrapper bookkeeping. const markerAt = tailText.lastIndexOf("\n" + EXIT_MARKER); if (markerAt === 0) { // The file is only the wrapper's "\n\n" — no command output. return 0; } if (markerAt !== -1) { - const noticeAt = tailText.lastIndexOf("\n" + TRUNC_NOTICE_PREFIX); + const afterMarker = tailText.slice(markerAt + 1); + const markerEnd = afterMarker.indexOf("\n"); + const markerLine = + markerEnd === -1 ? afterMarker : afterMarker.slice(0, markerEnd); + const noticePrefix = markerLine.includes(EXIT_MARKER_NOCAP_FLAG) + ? CAPFAIL_NOTICE_PREFIX + : markerLine.includes(EXIT_MARKER_TRUNC_FLAG) + ? TRUNC_NOTICE_PREFIX + : null; + const noticeAt = noticePrefix + ? tailText.lastIndexOf("\n" + noticePrefix) + : -1; const blockStart = noticeAt !== -1 && noticeAt < markerAt ? noticeAt : markerAt; let extra = 0; @@ -1406,10 +1584,25 @@ export default function (pi: ExtensionAPI) { // ── Cleanup ─────────────────────────────────────────────────────────────── - // Sweep stale per-project digest markers (.bgrun-used-*, .digest-nudge-*). - // They aren't session-scoped, so they'd otherwise accumulate one per project - // forever; a project that runs bgrun again re-writes its usage marker at - // spawn, so removing a stale one can at most re-enable one future nudge. + // Is the wrapper that owns this staging stem still running? It records its + // own pid next to its scratch files, so liveness is exact for a job started by + // ANY session sharing this jobs dir — unlike a log, whose protection needs the + // pid in the file name. + function stagingOwnerAlive(pidPath: string): boolean { + try { + const pid = parseInt(readFileSync(pidPath, "utf8").trim(), 10); + return Number.isFinite(pid) && isRunningPid(pid); + } catch { + // No liveness record (or unreadable) → treat as an orphan's leftovers. + return false; + } + } + + // Sweep stale per-project digest markers (.bgrun-used-*, .digest-nudge-*) and + // orphaned staging files. Markers aren't session-scoped, so they'd otherwise + // accumulate one per project forever; a project that runs bgrun again + // re-writes its usage marker at spawn, so removing a stale one can at most + // re-enable one future nudge. function sweepStaleMarkers(jobsDir: string, cutoff: number): void { let names: string[]; try { @@ -1417,21 +1610,31 @@ export default function (pi: ExtensionAPI) { } catch { return; } + // Staging files are only reclaimable when nobody owns them. Age alone used + // to delete a RUNNING job's fifo/flag — the wrapper's scratch files live for + // the whole job, so any aggressive cutoff killed them mid-run, silently + // removing the truncation notice and injecting a shell error into the log. + const stagingCutoff = Math.max(cutoff, Date.now() - STAGING_MIN_AGE_MS); for (const name of names) { + const isStaging = + name.startsWith(".tmp-") && + STAGING_SUFFIXES.some((suffix) => name.endsWith(suffix)); if ( + !isStaging && !name.startsWith(".bgrun-used-") && - !name.startsWith(".digest-nudge-") && - // Only OUR staging files (`.tmp---.log|.ec|.fifo|.cnt`), - // never an unrelated `.tmp-*` that happens to live in the dir. - !( - name.startsWith(".tmp-") && - STAGING_SUFFIXES.some((suffix) => name.endsWith(suffix)) - ) + !name.startsWith(".digest-nudge-") ) continue; try { const markerPath = join(jobsDir, name); - if (statSync(markerPath).mtimeMs > cutoff) continue; + const mtimeMs = statSync(markerPath).mtimeMs; + if (isStaging) { + if (mtimeMs > stagingCutoff) continue; + const stem = name.replace(/\.[a-z]+$/, ""); + if (stagingOwnerAlive(join(jobsDir, `${stem}.pid`))) continue; + } else if (mtimeMs > cutoff) { + continue; + } unlinkSync(markerPath); } catch { // ignore @@ -1961,8 +2164,8 @@ export default function (pi: ExtensionAPI) { try { // Pass command as argv — interpolation breaks on #, quotes, heredocs. // maxLogBytes 0 means "unlimited": keep the pre-ceiling wrapper exactly - // (head -c 0 is a hard error, not a no-op, so it cannot be routed - // through the capped path). + // (a zero-byte ceiling is meaningless, so it cannot be routed through + // the capped path). const capped = cfg.maxLogBytes > 0; const wrapper = capped ? cappedWrapper(cfg.maxLogBytes) @@ -1977,7 +2180,13 @@ export default function (pi: ExtensionAPI) { command, join(jobsDir, `${stem}.ec`), join(jobsDir, `${stem}.fifo`), - join(jobsDir, `${stem}.cnt`), + // Liveness, so a cleanup sweep can tell a running job's scratch + // files from an orphan's instead of judging them by age alone. + join(jobsDir, `${stem}.pid`), + // Truncation flag: written by the drain when bytes were left + // over. A file, not the drain's exit status, because the drain + // may still be running when the wrapper prints. + join(jobsDir, `${stem}.trunc`), ] : ["-c", wrapper, "bgrun", command], { @@ -2108,10 +2317,16 @@ export default function (pi: ExtensionAPI) { statsParts.push(`${logLines.toLocaleString("en-US")} lines`); // The cap is the one fact that changes what the others MEAN: the line // count, the last line and any digest describe only the bytes that - // were kept. Say so in the line the agent reads first. - const truncatedAt = readTruncationBytes(logPath); + // were kept. Say so in the line the agent reads first. A ceiling that + // could not be installed is the opposite case — the log is complete + // but unbounded — and that must not be silent either. + const capStatus = readCapStatus(logPath); + const truncatedAt = + capStatus?.kind === "truncated" ? capStatus.bytes : null; if (truncatedAt !== null) statsParts.push(`log truncated at ${formatBytes(truncatedAt)}`); + else if (capStatus?.kind === "ceiling-failed") + statsParts.push("no log ceiling (command ran uncapped)"); // Persist the done-state entry. pi.appendEntry("bgrun-job", { @@ -2565,18 +2780,27 @@ export default function (pi: ExtensionAPI) { const truncDetails = truncatedAt === null ? {} : { truncatedAtBytes: truncatedAt }; // Tail reads are bounded at LOG_READ_BYTES, so on a log past that window - // every view above is the end of a 2 MB slice — say so, or "not in the - // output" reads as "not in the log". + // every view above is the end of a slice — say so, or "not in the output" + // reads as "not in the log". The advertised maximum is the ceiling actually + // in force plus the wrapper's overhead, so it can cover a capped log + // (a max equal to the cap left its first bytes permanently unreadable). const windowNote = size > readWindow - ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(LOG_READ_BYTES_MAX)}) or use ctx_execute_file on the log path)` + ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(readWindowMax())}) or use ctx_execute_file on the log path)` : ""; // Content lines only: wrapper bookkeeping (exit marker, truncation notice) // and blanks are filtered BEFORE the window is sliced, so "last N lines" // means the last N content lines (matching pre-delta behavior) and // bookmarks count content lines. + // boundScanLines first: a window of very short lines (the `yes ''` runaway + // the ceiling exists for) is millions of lines in a few MiB, and splitting + // it all costs gigabytes of RSS on the host's main thread. // /\r?\n/ keeps CRLF logs from leaving a stray \r on every line. - const rawLines = content + const scan = boundScanLines(content); + const lineNote = scan.lineBoundHit + ? `\n\n(and only the last ${LOG_SCAN_LINES_MAX.toLocaleString("en-US")} lines of that window were scanned)` + : ""; + const rawLines = scan.content .split(/\r?\n/) .filter((l) => !isWrapperLine(l) && l.trim().length > 0); const total = rawLines.length; @@ -2629,7 +2853,7 @@ export default function (pi: ExtensionAPI) { content: [ { type: "text", - text: `(no new lines since last read — log at ${total} line${total === 1 ? "" : "s"})${capNote}${windowNote}`, + text: `(no new lines since last read — log at ${total} line${total === 1 ? "" : "s"})${capNote}${windowNote}${lineNote}`, }, ], details: { @@ -2667,7 +2891,7 @@ export default function (pi: ExtensionAPI) { content: [ { type: "text", - text: head + body + notes + capNote + windowNote, + text: head + body + notes + capNote + windowNote + lineNote, }, ], details: { @@ -2709,7 +2933,7 @@ export default function (pi: ExtensionAPI) { bytes: Type.Optional( Type.Number({ description: - "Search window in bytes (default 2097152 = 2 MiB, max 67108864 = 64 MiB). Widening only affects how much is SCANNED — the returned text stays capped.", + "Search window in bytes (default 2097152 = 2 MiB; capped at the configured log ceiling plus the wrapper's overhead — 67108864 = 64 MiB by default). Widening affects how much is SCANNED (and what the scan costs in CPU and memory) — the returned text stays capped.", minimum: 1, }), ), @@ -2781,15 +3005,25 @@ export default function (pi: ExtensionAPI) { const truncDetails = truncatedAt === null ? {} : { truncatedAtBytes: truncatedAt }; // Same window caveat as bgtail: the search covers only the last `window` - // bytes, so a miss on a bigger log means "not in the searched slice". + // bytes, so a miss on a bigger log means "not in the searched slice". The + // advertised maximum is the ceiling in force plus the wrapper's overhead, so + // it can cover a capped log. const windowNote = size > readWindow - ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(LOG_READ_BYTES_MAX)}) or use ctx_execute_file on the log path)` + ? `\n\n(searched the last ${formatBytes(readWindow)} of ${formatBytes(size)} — the earlier bytes were not searched; pass a larger \`bytes\` (max ${formatBytes(readWindowMax())}) or use ctx_execute_file on the log path)` : ""; + // Bound the LINE count before splitting: a window of very short lines is + // millions of lines in a few MiB, and materializing them costs ~100 bytes + // each (>3 GB measured for a 64 MiB window) — on the main thread, in the + // very log class the ceiling exists for. The caveat says when it bit. + const scan = boundScanLines(content); + const lineNote = scan.lineBoundHit + ? `\n\n(and only the last ${LOG_SCAN_LINES_MAX.toLocaleString("en-US")} lines of that window were searched)` + : ""; // /\r?\n/ normalizes CRLF (a trailing \r would break $-anchored patterns // and leak into output); blank lines are KEPT so L numbers match the // file. A trailing empty split element is dropped; "" yields zero lines. - const split = content === "" ? [] : content.split(/\r?\n/); + const split = scan.content === "" ? [] : scan.content.split(/\r?\n/); if (split.length > 0 && split[split.length - 1] === "") split.pop(); const rawLines = split.filter((l) => !isWrapperLine(l)); // Match under a wall-clock budget in a worker: a caller-supplied regex can @@ -2839,7 +3073,7 @@ export default function (pi: ExtensionAPI) { if (matchIdx.length === 0) { return { content: [ - { type: "text", text: `${header} — none${truncNote}${windowNote}` }, + { type: "text", text: `${header} — none${truncNote}${windowNote}${lineNote}` }, ], details: { id, @@ -2881,7 +3115,7 @@ export default function (pi: ExtensionAPI) { content: [ { type: "text", - text: `${header}${capNote}\n${text}${notes}${truncNote}${windowNote}`, + text: `${header}${capNote}\n${text}${notes}${truncNote}${windowNote}${lineNote}`, }, ], details: { @@ -2929,7 +3163,7 @@ export default function (pi: ExtensionAPI) { bytes: Type.Optional( Type.Number({ description: - "Search window in bytes (default 2097152 = 2 MiB, max 67108864 = 64 MiB). Widening only affects how much is SCANNED — the returned matches stay capped (~50 matches, ~8KB).", + "Search window in bytes (default 2097152 = 2 MiB; capped at the configured log ceiling plus the wrapper's overhead — 67108864 = 64 MiB by default). Widening affects how much is SCANNED (and what the scan costs in CPU and memory) — the returned matches stay capped (~50 matches, ~8KB).", minimum: 1, }), ), From 73a8327c1259ce4b8a2b1dfd5da4538988bd2953 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:27:42 -0400 Subject: [PATCH 08/13] ci: check the publish allowlist with npm pack The tarball that ships is built by `npm publish` (release.yml, OIDC trusted publishing), so the allowlist must be checked with the packer that actually produces it. Both packers emit the same 7 files today; keeping that true is the point of the step. npm is preinstalled on the runner, so ci.yml stays bun-only for every other step. Also fix the guard's silent-pass hole: a failing `bun pm pack` printed `? files` and the step still went green, because the leak greps below cannot fail on an empty listing. It now fails on a non-zero pack status or a missing file count, and the count is extracted with sed (npm lowercases "total files:", and GNU `grep -oP` was never portable). --- .github/workflows/ci.yml | 28 ++++++++++++++++++++++------ 1 file changed, 22 insertions(+), 6 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 346da57..58572df 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -28,7 +28,7 @@ jobs: # listing), so a Node toolchain here would be dead weight. The one thing a # Node job would add is the V8/worker_threads side of bggrep's bounded # matching — verified by hand with `node --test extension/index.test.ts` - # (183 pass, ~16s). Re-run that by hand after touching the bggrep worker. + # (193 pass, ~20s). Re-run that by hand after touching the bggrep worker. - name: Set up Bun uses: oven-sh/setup-bun@v2 with: @@ -47,12 +47,28 @@ jobs: id: tests run: bun test extension/index.test.ts - - name: bun pm pack --dry-run (files allowlist sanity) + # npm, not bun, for THIS step only: the tarball that ships is built by + # `npm publish` (release.yml, OIDC trusted publishing), so the allowlist + # must be checked with the packer that actually produces it. npm is + # preinstalled on the runner — no setup-node, no second toolchain — and + # today both packers emit the same 7 files; that agreement is what this + # step is here to keep true. + - name: npm pack --dry-run (files allowlist sanity) id: pack run: | - pack_output=$(bun pm pack --dry-run 2>&1) + pack_status=0 + pack_output=$(npm pack --dry-run 2>&1) || pack_status=$? echo "$pack_output" - file_count=$(echo "$pack_output" | grep -oP 'Total files:\s*\K[0-9]+' || echo "?") + # sed, not grep -oP: no GNU/BusyBox difference to trip over, and the + # casing differs between packers ("total files:" vs "Total files:"). + file_count=$(echo "$pack_output" | sed -n 's/.*[Tt]otal files:[[:space:]]*\([0-9][0-9]*\).*/\1/p' | tail -1) + # npm pack failing, or printing no file count, means the allowlist was + # never actually checked — the greps below cannot fail on it. Treat + # that as a failure instead of a green step reporting "? files". + if [ "$pack_status" -ne 0 ] || [ -z "$file_count" ]; then + echo "::error::npm pack --dry-run failed (exit ${pack_status}) or printed no file count — allowlist NOT verified" + exit 1 + fi echo "file_count=${file_count}" >> "$GITHUB_OUTPUT" # Enforce the allowlist: test files and other non-runtime files must # never ship in the published tarball (they bloat installs and leak @@ -87,7 +103,7 @@ jobs: echo "|---|---|" echo "| tsc --noEmit | ${TSC_RESULT} |" echo "| tests | ${TESTS_OUTCOME} |" - echo "| bun pm pack --dry-run | ${PACK_OUTCOME} (${PACK_FILES} files in tarball) |" + echo "| npm pack --dry-run | ${PACK_OUTCOME} (${PACK_FILES} files in tarball) |" echo "" echo "Ref: \`${HEAD_SHA}\`" } > "$body_file" @@ -121,7 +137,7 @@ jobs: echo "|---|---|" echo "| tsc --noEmit | \`${TSC_RESULT}\` |" echo "| tests | \`${TESTS_OUTCOME}\` |" - echo "| bun pm pack --dry-run | \`${PACK_OUTCOME}\` — ${PACK_FILES} files in tarball |" + echo "| npm pack --dry-run | \`${PACK_OUTCOME}\` — ${PACK_FILES} files in tarball |" echo "" echo "Ref: \`${COMMIT_SHA}\`" } >> "$GITHUB_STEP_SUMMARY" From e39fb13cbd00f9afe6424bcf1d7bf8d9eee67b40 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:27:42 -0400 Subject: [PATCH 09/13] docs: state the ceiling's reader contract (marker flag, window and line bounds) Reading a capped log is now honestly bounded and honestly described: the flag lives in the exit marker rather than in printable text (so a command echoing a notice-shaped line is content, not a signal), the widest `bytes` window is the ceiling plus 4 KiB so it can span the whole kept log, a window is additionally limited to its last 500k lines, and when that bites bgtail/bggrep say so. --- README.md | 33 +++++++++++++++++++++++---------- skill/run-bg/SKILL.md | 6 +++++- 2 files changed, 28 insertions(+), 11 deletions(-) diff --git a/README.md b/README.md index 6c943cd..55d6aca 100644 --- a/README.md +++ b/README.md @@ -148,16 +148,29 @@ default **64 MiB**, `0` = unlimited): cap are drained and discarded instead of SIGPIPE'ing the producer into `141`. - It is **not silent**. The log carries `[pi-bgrun] output truncated at bytes (first bytes kept)` on the line - before the exit marker — filtered out of content readers exactly like the exit - marker — and every surface the agent reads is labelled instead: the wake's - Stats line gains `log truncated at 64 MiB`, `bgtail` and `bggrep` append a - note and report `truncatedAtBytes` in their details, and a configured digest - scorecard is **skipped** rather than run against a log that lost its end — - summaries and failure lists live at the end, so its numbers would be - confidently wrong. Treat a skipped digest on a capped job as "unknown", not - "no failures". -- Cost: a capped job runs through a few extra processes (`tee`, `head`, `wc`) — - a few tens of milliseconds of job startup, no steady-state overhead. + before the exit marker, and the marker line itself carries the flag + (`__BGRUN_EXIT__=0 truncated=67108864`) — readers trust that marker, never + printable text, so a command that echoes something that looks like the notice + cannot make its own log look capped. The notice is filtered out of content + readers exactly like the exit marker, and every surface the agent reads is + labelled instead: the wake's Stats line gains `log truncated at 64 MiB`, + `bgtail` and `bggrep` append a note and report `truncatedAtBytes` in their + details, and a configured digest scorecard is **skipped** rather than run + against a log that lost its end — summaries and failure lists live at the end, + so its numbers would be confidently wrong. Treat a skipped digest on a capped + job as "unknown", not "no failures". +- Reading a capped log stays readable-whole: the widest `bytes` window is the + ceiling **plus 4 KiB** (not the ceiling itself, which a capped log always + exceeds by its notices and marker), so `bytes: 67108864` still spans the whole + kept log. Windows are additionally limited to their last 500 000 lines — + materializing a 64 MiB window of one-character lines would cost gigabytes of + strings — and when that line bound trims a window, `bgtail`/`bggrep` say so in + the same labelled way instead of silently answering from a subset. +- Cost: a capped job runs through one copier process (`perl` where available, + else `dd`/`head`) reading the job through a fifo, plus a bounded drain wait — + a few tens of milliseconds of job startup, no steady-state overhead. The + copier is also what drains the stream past the cap, so the producer is never + SIGPIPE'd. - Configure `maxLogBytes: 0` for the previous uncapped behavior, e.g. when the whole log must survive for `ctx_execute_file`. diff --git a/skill/run-bg/SKILL.md b/skill/run-bg/SKILL.md index 5537235..f4fbfba 100644 --- a/skill/run-bg/SKILL.md +++ b/skill/run-bg/SKILL.md @@ -148,7 +148,11 @@ that expensive rather than merely rude. Aggregate, then cap what you print: skipped rather than scored against an incomplete log — so on a capped job, read a missing digest as "unknown", **not** as "no failures", and do not re-run the command to see the missing tail; raise the ceiling if you need the - whole log. + whole log. The flag lives in the exit marker (`__BGRUN_EXIT__=0 + truncated=`), so treat a notice-looking line printed by the command itself + as content, not as a cap signal. A search window is also limited to its last + 500 000 lines: when that bites, `bgtail`/`bggrep` say so — a "none" from a + trimmed window means the head was not searched. - Logs default to `/.pi-bgrun/jobs` in a repo — project-scoped is the model (`~/.pi-bgrun/jobs` is a deprecated fallback for a cwd with no project root; an absolute `PI_BGRUN_DIR`/`jobsDir` still works but is legacy). Project-local dirs are From e72b9aa3dd1ad3718d5a2754e4a3089e0f25e150 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:27:42 -0400 Subject: [PATCH 10/13] docs: add the log-size-ceiling implementation brief The design record for the ceiling and the seven review passes behind it: why the cap keeps the first bytes, why the mechanism lives inside the detached tree, the fifo/copier shape and the alternatives it beat, and each defect an adversarial pass reproduced against the previous shape. Not part of the published tarball (package.json files[]). --- LOG-SIZE-CEILING.md | 559 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 559 insertions(+) create mode 100644 LOG-SIZE-CEILING.md diff --git a/LOG-SIZE-CEILING.md b/LOG-SIZE-CEILING.md new file mode 100644 index 0000000..e853cb2 --- /dev/null +++ b/LOG-SIZE-CEILING.md @@ -0,0 +1,559 @@ +# bgrun: child stdout size ceiling (Option A) — implementation brief + +Status: IMPLEMENTED and COMMITTED on `lloydsk/log-size-ceiling`, base +`8cba8d9`. Every commit verified green on its own tree (`tsc --noEmit` + 183/183 +under bun); HEAD also verified under `node --test` (183/183). + +``` +f137a9f ci(release): document why publishing stays on npm, not bun publish +63a1c15 test: cover the bggrep sync fallback (the path without worker_threads) +c2f4207 test: verify the bggrep worker abort path, and fix a vacuous pathological test +1dcf365 ci: run everything on bun, drop the Node toolchain +311cd48 docs: deprecate the machine-global jobs dir; resolve home consistently +e7f0669 feat: cap background job log output, and make readers honest about it +``` + +Feature diff: `extension/index.ts`, `extension/index.test.ts`, `README.md`, +`skill/run-bg/SKILL.md` (+1178/−89 across the three commits, plus the CI file). +This brief is untracked — it is the PR body, not a shipped artifact. + +Deviations from the design below, decided during implementation: + +- The cap value is baked into the generated wrapper script rather than passed as + argv; argv is now `$1` command, `$2` ecfile, `$3` fifo, `$4` countfile. +- If `mkfifo` fails, the wrapper falls back to the **uncapped** path — losing + output is worse than losing the ceiling. +- `countLogLines` returns `null` (line stat omitted) rather than a partial count + when the log exceeds its 64 MiB scan bound, and reads the tail offset from + `fstatSync`. It also returns `null` if the file's size changes mid-scan. +- `tailBookmarks` is declared next to `jobs` (so cleanup can evict it without a + TDZ hazard) and additionally bounded by `TAIL_BOOKMARK_CAP = 1000` via a + `rememberTail()` helper, because cleanup only evicts jobs whose log it removed. +- The staging-suffix set is `STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".cnt"]`. +- Two pre-existing issues surfaced while verifying: this worktree had drifted + `@types/node` 26.4.1 (spec `^24.0.0`), which made the pristine base fail + `tsc --noEmit` — fixed with `bun install --frozen-lockfile` (now 24.13.5), not + by changing source. And the wake-stats test pinned `Stats: 0.0s` for an + instant job; the capped wrapper spawns a few extra processes, so it is now + asserted by shape (`/Stats: \d+\.\d+s, 1 lines/`) instead of pinning the host. +- Tests written: cap+notice+head-kept+exit-code, notice-excluded-from-stats and + from last-line, exact-cap boundary, `0` = uncapped, no staging strays, stale + staging reclaimed by the sweep (unrelated `.tmp-*` kept), bgtail/bggrep on a + capped log plus the post-cap bytes being unsearchable, a multi-megabyte flood + still exiting with its own code (no SIGPIPE), and `resolveConfig` normalization + (blank env must not disable the cap). + +Follow-on (added 2026-09-20, second pass): **truncation is agent-visible**, not +just on disk. The first pass filtered the notice out of every reader, which meant +nothing told the agent a log had been capped — and the shipped digest presets +(jest/pytest/go-test/junit-xml all read the log's END) would then report +`fail: 0` for a run whose failures were past the cap. Now: + +- `parseTruncationFromContent()` (exact: the notice counts only when it is the + line immediately before the exit marker) + `readTruncationBytes()` (decided + from the standard 256 KB tail slice — no extra IO) + `formatBytes()`. +- The wake's Stats line gains `log truncated at 64 MiB`. +- A selected digest is **skipped** with an explanation instead of run. +- `bgtail`/`bggrep` append a labelled note and report `truncatedAtBytes` in + their details (`bgtail` also on its delta early-return path). +- README + `skill/run-bg/SKILL.md` state the rule: on a capped job, a missing + digest means "unknown", not "no failures". +- Context cost: zero for under-cap jobs; for capped jobs one extra clause in the + Stats line and one note line per reader call (the alternative — a confidently + wrong scorecard — costs more and misleads). + +Follow-on (added 2026-09-20, third pass): **context economics vs context-mode**, +measured on a synthetic 1.29 MB / 20 000-line test log (raw ≈ 1.29 MB): + +| path | context cost | +| --- | --- | +| raw dump | 1,287,215 chars | +| wake alone (exit, duration, lines, last line, digest, truncation) | ~200 chars | +| `bgtail` (last 40, condensed, 8 KB cap) | 2,600 chars | +| `bggrep` (failure regex, ≤50 matches) | 873 chars | +| `ctx_execute_file` equivalent | 744 chars stdout **+ 221 chars of code the model writes** | + +Output envelopes are comparable, so the read tools do not win on bytes; they win +on zero-code calls, in-memory delta bookmarks (repeat polls ~free), job-id +resolution, a regex wall-clock budget, and no FTS5 side effects (`ctx_execute_file` +auto-indexes stdout >100 KB and switches to BM25 sections above 5 KB with `intent`). +The wake is the real saver — most jobs need no read at all. + +Two defects found while checking, both fixed: + +1. The claim that a "project-sandboxed `ctx_execute_file` cannot reach the global + jobs dir" was **false** — its schema takes "absolute file path or relative to + project root" and its only check is the agent's own Read-deny policy + (`checkFilePathDenyPolicy`); there is no project-root confinement. Corrected in + README (×3), `skill/run-bg/SKILL.md` (×2) and bggrep's tool description, and + reframed: the real advantage is resolving the job id, not reach. +2. `bgtail`/`bggrep` read only the **last 2 MB** (`LOG_READ_BYTES`, one call site + in `resolveLogForJob`) — with a 64 MiB ceiling that silently hides 97% of a + capped log, and "— none" reads as "no failures anywhere". Both readers now + append a window caveat when `size > LOG_READ_BYTES`, and the SKILL points at + `ctx_execute_file` as the whole-file path (the only tool that covers >2 MB). + +Third pass, part 2 — the window became an argument (this was the user's read on +defect 2, and it was right): + +- **The two bounds are independent, which the first pass blurred.** `maxLogBytes` + bounds bytes *written to disk* (inside the detached wrapper); `LOG_READ_BYTES` + bounds bytes *scanned* by the readers (`resolveLogForJob`). The cap never + bounded reads — past 2 MB the readers always saw a slice, and a legitimate + 64 MiB log made that slice 3% of the file. +- **`bytes` param on `bgtail` and `bggrep`**, clamped by `clampReadWindow()`: + absent/garbage/≤0 → the 2 MiB default; wider than `LOG_READ_BYTES_MAX` + (= `DEFAULT_MAX_LOG_BYTES`, since no job can have written more than the + ceiling) → the ceiling. Both report `windowBytes` in details. +- **A wide window costs latency and memory, NOT context.** Only the scan grows; + the returned text stays capped by the condenser (~8 KB, ≤50 matches). Asserted + directly: an 8 MiB-window search over a 2.7 MB log finds a marker the default + window misses while the result stays <9000 chars. +- **Bug caught while wiring it:** a changed window moves the window's *first* + line, so the stale "log was replaced" heuristic fired first and mislabelled a + widened read. `windowChanged` now beats `replaced`, and bgtail resets the delta + with `search window changed since last read — showing full tail` instead of + reporting pages of "new" lines that were merely never looked at. +- The window caveat now names the actual window and the escape hatch: `pass a + larger 'bytes' (max 64 MiB) or use ctx_execute_file on the log path`. + +Third pass, part 3 — **the machine-global jobs dir is deprecated** (user call, +docs-only, staged): + +- Project-scoped logs are the model; `PI_BGRUN_GLOBAL_DIR` and the + `~/.pi-bgrun/jobs` destination are marked deprecated in the README env table, + the Roadmap, and the run-bg SKILL, with a new `### Deprecated: machine-global + jobs dir` section (why project-scoped won, what is lost, 3-step migration). +- **Nothing breaks today:** existing absolute `jobsDir`/`PI_BGRUN_DIR` behave + exactly as before; removal is reserved for a future major. +- **The fallback cannot be removed, only demoted:** a cwd with no project root + still resolves to `~/.pi-bgrun/jobs` (`globalJobsDir()` at :733/:735). The + alternative is scattering logs into an arbitrary cwd, which the code + deliberately refuses. It becomes an undocumented internal fallback. +- **`PI_BGRUN_GLOBAL_DIR` is also the test seam** (`index.test.ts:75`, plus two + more sites) for staying off the real `~/.pi-bgrun`, so "remove the knob" needs + a HOME-override replacement in the same change. +- **No runtime deprecation warning, deliberately:** it would fire on every + test-run config and cannot distinguish a test seam from a real user. Docs are + the honest lever; add the warning on request. + +Fourth pass — **Node leaves CI, and the seam stops being the deprecated knob**: + +- **`bun pm pack --dry-run` is a real substitute** for `npm pack --dry-run` (it + prints the packed file list and `Total files: N`), and `bunx`/`bun run lint` + cover `npx tsc`. So every CI step ran on Bun already, with a Node toolchain + installed for nothing. `ci.yml` is now **bun-only**: no `setup-node`, steps are + `bun install --frozen-lockfile` / `bun run lint` / `bun test + extension/index.test.ts` / `bun pm pack --dry-run` (guard re-pointed at Bun's + `Total files:` casing). All four verified locally, including the tarball + allowlist guard parsing 7 files and rejecting test-file patterns. +- **What dropping Node costs:** the V8/worker_threads side of bggrep's bounded + matching is no longer exercised in CI. Bun *does* implement + `node:worker_threads` (verified: `typeof Worker === "function"`), so the worker + *mechanism* is still covered — only V8's backtracking behaviour is not. Manual + insurance, recorded in a comment in `ci.yml`: `node --test + extension/index.test.ts` passes **183/183 in ~16s** (run 2026-09-20, Node + 24.15). Re-run it by hand after touching the worker path. +- **`fold-in #3` is therefore resolved as "no Node job"**, not deferred. +- **The test seam no longer rides on the deprecated knob.** `PI_BGRUN_GLOBAL_DIR` + was the only way to keep tests off the real `~/.pi-bgrun`, because **Bun's + `os.homedir()` ignores `$HOME`** (verified: unchanged after mutating HOME in + process) — the old-looking `homeDir()`-style comment in `resolveConfig` was the + maintainers working around exactly that. Fix: a `homeDir()` helper that is + HOME-first (`process.env.HOME || homedir()`), used by `globalJobsDir()`, + `expandTilde()`, `findProjectRoot()` and the user-config path. Node already + behaved this way, so this *aligns* the runtimes rather than inventing policy; + the test file now pins `HOME` and leaves `PI_BGRUN_GLOBAL_DIR` unset, so + retiring the knob is a docs+3-line delete instead of a test rewrite. + Verified green under **both** runners (183/183 bun, 183/183 node). +- `PI_BGRUN_GLOBAL_DIR` stays *supported* (deprecated) — the deprecation is about + the machine-global destination, not about this override, which is also the + escape hatch for anyone who genuinely wants one shared dir. + +Fifth pass — **the V8 concern, measured, and a vacuous test fixed**: + +| engine | `^(a+)+$` over `"a"×n + "!"` | | +| --- | --- | --- | +| Node 24.15 (V8/Irregexp) | n=100 → **killed at 10s** | exponential backtracking | +| Bun 1.3.6 (JSC) | n=100…5000 → **~250ms, constant** | no backtracking blowup | + +So the hazard the worker+budget exists for is real and *engine-specific*: on +JSC the pathological case effectively does not exist, which is why a Bun-only CI +cannot verify the guard by input. Two things follow: + +1. **The shipped test was vacuous.** `bggrep: a pathological regex returns within + the budget instead of hanging` wrote 60 000 "a"s plus a "b" — but bggrep + pre-truncates each line to `BGGREP_LINE_CAP = 10 000` *before* matching, so + the "b" was cut away and `^(a+)+$` matched in **0ms on both engines**. The + failing character now sits inside the cap window: 2004ms on Node (budget + trips, worker terminated), ~250ms on Bun. +2. **The abort path now has an engine-independent test.** + `matchLinesWithBudget()` takes an injectable worker body (optional param, + defaulting to `BGGREP_WORKER_SOURCE`) and is exported for tests, so a worker + that never returns proves the budget ends it — ~300ms, on both engines. + That is the assertion an input-driven pattern cannot make portably. + +3. **The sync fallback is covered too.** `matchLinesSyncBounded` runs only where + `node:worker_threads` is missing — never on Node or Bun — so nothing exercised + it: a regression there would ship silently and surface as "bggrep behaves + differently in that environment". Exported for tests (like the other seams) + and covered by parity with the worker path (matches, misses, the per-line cap, + a bad pattern's `invalid` outcome) plus both budget guards: fired before the + first line when the budget is already spent, and re-checked mid-scan (0 ms + budget over 300 000 lines aborts rather than finishing the corpus). + +Sixth pass — **publishing stays on npm** (asked: any downside to `bun publish`?). +`bun publish` has no OIDC trusted-publishing and no provenance support (auth is a +long-lived `NPM_CONFIG_TOKEN`; the documented flags carry no provenance option), +while `release.yml` relies on `id-token: write`, stores **no** token, and gets +provenance attestations for free from trusted publishing. Switching would trade a +tokenless, attested release for a stored bearer credential — so the release path +keeps Node+npm deliberately, unlike the test job, and a comment next to the Node +setup says why. Functional parity was *not* the issue: `--access`, `--tag`, +`--dry-run`, `--otp` and registry config all exist in Bun, lifecycle-script +differences are moot (no `prepack`/`prepublishOnly`/`prepare` here), and +`--tolerate-republish` is actually nicer than npm for CI re-runs. + +Consequence for the CI decision: `bun test` now covers the worker *mechanism* +deterministically (abort path + budget plumbing + the fixed stress input) and +the fallback's contract, and `node --test` remains the only way to exercise V8's +own backtracking — a manual command, noted in `ci.yml`. Suite: 186/186 under +both runners. + +## Problem + +`bgrun` redirects the child's stdout+stderr straight to the log fd +(`spawn("sh", ["-c", wrapper, "bgrun", command], { stdio: ["ignore", logFd, logFd], detached: true })`, +`extension/index.ts` ~:1765). The read side is bounded on this base +(`readLogSlice()` @:221 — `LOG_TAIL_BYTES = 256 KB` for the exit marker, +`LOG_READ_BYTES = 2 MB` for `bgtail`/`bggrep`), but the **write side is +unbounded**: a runaway job (`yes`, a spew loop, a pathological build) fills the +disk and can take the machine down. Secondary effect: `countLogLines` (:1134) +streams the whole file at exit (bounded memory, unbounded IO). + +## Constraints (any fix must respect these) + +1. The cap must live **inside the detached process tree** — pi can exit at any + time. No parent-side streaming (that would break "survives pi crashing"). +2. The `__BGRUN_EXIT__` marker must remain the **last non-empty line** — + `parseExitFromContent` (:256) walks backwards to the last non-blank line and + treats only that as completion evidence (a marker that is not last is job + output that happens to contain the string). `readLogSlice(LOG_TAIL_BYTES)` + finds it as long as it stays in the final 256 KB — which a head cap + guarantees, since the whole capped log is ≤ CAP + overhead. +3. One writer, one offset — two writers into the same file corrupt it (this + includes the exit-code file; see below). +4. Cap only the redirected stdout/stderr, **never the command's own files**. +5. `maxLogBytes: 0` means unlimited and MUST produce the **current** wrapper + verbatim. It must not be routed through the capped pipeline. + +## Chosen design: Option A — in-tree head cap, job survives + +Replace the current wrapper: + +```sh +sh -c "$1"; ec=$?; printf '\n__BGRUN_EXIT__%d\n' "$ec"; exit "$ec" +``` + +with a capped pipeline plus an exact byte counter: + +```sh +# argv: $1 = command, $2 = ecfile, $3 = cap, $4 = fifo, $5 = countfile +count="$5"; rm -f "$4" "$count"; mkfifo "$4"; ( wc -c <"$4" >"$count" ) & ctr=$! +{ sh -c "$1" 2>&1; ec=$?; printf '%d' "$ec" >"$2"; } \ + | tee "$4" | { head -c "$3"; cat >/dev/null; } +wait "$ctr" +total=$(cat "$count"); ec=$(cat "$2") +rm -f "$2" "$4" "$count" +if [ "${total:-0}" -gt "$3" ]; then + printf '\n[pi-bgrun] output truncated at %s bytes (first %s bytes kept)\n' \ + "$3" "$3" +fi +printf '\n__BGRUN_EXIT__%d\n' "$ec"; exit "$ec" +``` + +(The notice literal above is generated from `TRUNC_NOTICE_PREFIX`; it is a +constant, so it is safe to interpolate into the wrapper's format string.) + +Why this shape: + +- `head -c CAP` writes the first CAP bytes to the wrapper's stdout (the log fd). +- `cat >/dev/null` then drains the rest, so the producer never gets SIGPIPE and + the **job runs to completion** with its real exit code (unlike Option B). +- `tee "$fifo"` runs a *second*, uncapped copy of the stream into `wc -c`, so + the wrapper knows the true total. `total > CAP` is the truncation test. +- The command's exit status is captured to `$2` *by the producer group* + (redirected to a file, not the pipe), because a pipeline's `$?` is the + reader's. The wrapper reads `$2` and prints the marker. Constraint 3 holds: + only the producer writes `$2`, only `wc` writes `$5`. +- Single writer at a time into the log: the reader stage writes to fd1, then the + wrapper's `printf` writes to the same fd1 — same offset, no corruption. +- Works with pi dead: the whole thing is inside the detached tree. + +Accepted price: the log keeps the **first** CAP bytes, not the tail. There is no +portable in-tree *tail* cap — a ring buffer needs a helper binary, and a circular +file breaks every existing reader (marker-at-tail, `bgtail`, `bggrep`). A job +that emits > CAP is almost always a runaway, so the head is the useful part. + +### Truncation detection: why not the simple counters + +Measured on this machine (macOS 25.6, BSD `head`) while writing this brief: + +| detection idea | result | +| --- | --- | +| count bytes left after `head -c CAP` (`cat \| wc -c`) | **silently 0** whenever the overshoot is smaller than `head`'s read buffer: `CAP=100 N=101` → 0, `CAP=1000 N=1500` → 0, `CAP=8192 N=8193` → 0; only `CAP=65536 N=65537` → 1. `head` over-reads into its buffer and discards the excess. | +| `wc -c cap`, append: + +``` +[pi-bgrun] output truncated at bytes (first bytes kept) +``` + +Details that matter: + +- **Leading `\n` is required.** Without it the notice glues onto the truncated + last byte (`…aaa[pi-bgrun] output truncated…`), which corrupts line counts and + `bggrep` line numbers. Verified in the prototype. +- Define one constant (`TRUNC_NOTICE_PREFIX = "[pi-bgrun] output truncated"`) and + filter it wherever `EXIT_MARKER` is filtered today: `countLogLines`' tail + accounting ("N lines" must not count the notice) and the wake's last-line + pick. Otherwise the wake reports the notice as the job's last output. +- `bggrep` will match the notice if the caller greps that phrase (e.g. grepping + a bgrun log for `truncated`). That is acceptable and should be documented in + `skill/run-bg/SKILL.md` rather than worked around. + +## Config + env + +- New config field `maxLogBytes` (number, bytes), plus `PI_BGRUN_MAX_LOG_BYTES`. +- Default **64 MiB**. `0` = unlimited (documented escape hatch) → take the + legacy uncapped wrapper path, no fifo, no reader. +- Read at spawn time (per-job), so a config edit affects the next job only. +- Validate like the other numeric fields: finite, integer, `>= 0`; reject `NaN` + / negative / non-number to the default. + +## Files / plumbing + +- `extension/index.ts`: + - config field + normalization + env merge (next to `cleanupDays`, :950-1003). + - wrapper construction + spawn argv in the `bgrun` tool `execute` (~:1750). + The wrapper already receives `command` as `$1`; add `$2` ecfile, `$3` cap, + `$4` fifo, `$5` countfile. + - `TRUNC_NOTICE_PREFIX`, and the marker-filtering updates in + `countLogLines` (:1134) and the last-line pick. + - help/description text. +- Staging artifacts, next to the log in the jobs dir (same convention as the + existing `.tmp---.log`): `.tmp---.ec`, + `…fifo`, `…cnt`. The jobs dir is guaranteed writable (the log fd already lives + there), unlike `TMPDIR`. +- **Widen the sweep predicate.** `sweepStaleMarkers` (:1220) currently reclaims + only `.tmp-*` names ending in `.log`; the new `.ec`/`.fifo`/`.cnt` strays + (left only by a hard kill) would never be reclaimed. Match + `.tmp-*.(log|ec|fifo|cnt)`. Do **not** rename the ec file to `.log` to reuse + the existing predicate: `.log`-suffixed files are treated as job logs by + `adoptForeignJobs` / `cleanOldJobs` / `bgstatus`, and the `.tmp-` skip exists + only in one function (:346). +- In the normal path the wrapper removes its own artifacts (verified); the sweep + is for kill -9 / power loss only. +- `README.md`: env-table row + a short "Log size ceiling" note (state the + head-cap tradeoff explicitly). +- `skill/run-bg/SKILL.md`: one line so the agent knows logs can be truncated and + the notice line is not command output. + +## Tests + +The list below is the acceptance sketch from planning. What actually shipped is +these 18 tests (the earlier 165 are unchanged and pass against the capped +wrapper, which is the transparency check for bgtail/bggrep/digest/adopt): + +| # | Test | +| --- | --- | +| 1 | maxLogBytes keeps the first N bytes, notes the truncation, preserves the exit code | +| 2 | the truncation notice is not job output — not counted, not the last line | +| 3 | a job that outruns the cap by megabytes still finishes with its own exit code (no SIGPIPE) | +| 4 | a log at exactly the cap is not called truncated; one byte over is | +| 5 | maxLogBytes 0 leaves the log uncapped | +| 6 | a capped job leaves no staging files behind | +| 7 | stale staging files (.ec/.fifo/.cnt) are reclaimed; unrelated `.tmp-*` are not | +| 8 | bgtail/bggrep work on a capped log and only see what was kept | +| 9 | resolveConfig: maxLogBytes accepts 0 and ignores blank/invalid values | +| 10 | formatBytes / parseTruncationFromContent: the notice counts only as the wrapper's own line | +| 11 | wake: a capped job says so in the Stats line; an uncapped one does not | +| 12 | wake digest: a scorecard is skipped, not misreported, when the log was capped | +| 13 | bgtail/bggrep: a capped log is labelled and carries truncatedAtBytes | +| 14 | bgtail/bggrep: no truncation label on an uncapped log | +| 15 | a log bigger than the 2 MB read window says it was only partly searched | +| 16 | no window caveat on a small log | +| 17 | `bytes` widens the search window without widening the output | +| 18 | clampReadWindow: default, explicit, garbage, and ceiling | + +Original sketch below. + +1. Generator > CAP → log size is exactly `CAP + notice + marker + leading + newlines` (not merely "≤ CAP + overhead" — pin the real ceiling), marker + present and last, exit code correct. +2. Truncation notice present when capped; absent when under; **exact-CAP output + is not reported as truncated** (boundary). +3. Exit code preserved exactly (0 and non-zero) through the pipeline. +4. Notice is not counted by `countLogLines` and is not the wake's last line. +5. `bgtail`/`bggrep` on a capped log: content returned, marker found, and + `readLogSlice`'s `truncated: true` (tail window < file) is asserted as a + *distinct* signal from the cap notice — do not conflate them. +6. `maxLogBytes: 0` disables the cap (full output written, no notice, no fifo + created, legacy wrapper path used). +7. `$ecfile`/fifo/countfile removed after use (no stray `.tmp-*` beyond the + log); a simulated stale one is reclaimed by `sweepStaleMarkers`. +8. Existing behavior unchanged: pipes, `&&`, `#`, quotes, heredoc commands. +9. Notice has a leading newline — assert the byte before the notice is `\n`. + +## Rejected alternatives + +- **C — pi-side watchdog** (stat running logs, kill + truncate tail): soft bound + only while pi lives; overshoot = write-rate × poll interval; unbounded if pi + died. Keeps the tail, but doesn't keep the promise. +- **B — `head -c` without the `cat` drain**: producer dies on SIGPIPE (141); + hostile to legitimately verbose builds. +- **D — `ulimit -f`**: caps *every* file the job writes (artifacts, downloads) + and kills it (SIGXFSZ/153). Opt-in only, not a default. +- **E — document + trim finished logs**: no bound while running. +- **F — `dd bs=1 count=CAP`** as an exact front stage: no over-read, but one + read syscall per byte (64 MiB cap = 64M syscalls) — unusable. + +Revisit C only if tail retention turns out to matter in practice. + +Estimate: ~2.5–3 h including tests and the two fold-ins below (the earlier ~1.5 h +estimate predated the detector rework, the `0` branch, and reconciliation with +PR #11 — the rebase itself is now done). + +## Fold-in follow-ups (from the 2026-09 adversarial review) + +**Status (2026-09-20): both closed, see the seventh pass.** +**#1** closed — `countLogLines` now takes the tail offset from `fstatSync(fd).size` +and refuses (returns `null`) when the file exceeds `readWindowMax()`, so the scan +is bounded and the tail pread can never be misplaced by a bound. +**#2** closed — the map is evicted on log removal (`cleanOldJobs`, +`cleanSessionJobs`) *and* hard-capped by `TAIL_BOOKMARK_CAP` with +oldest-insertion eviction, so it cannot grow unboundedly even without cleanup. +**#3** resolved as "no Node job" (fourth pass, fourth bullet), not deferred. + +Both were found on the review branch (`lloydsk/Feedback-Improvements`, PR #11) +and deliberately deferred here, because a log size ceiling is the proper fix for +both — do them as part of this work, not separately. Re-verified against +`8cba8d9`: both were still open. + +### 1. `countLogLines` streams the whole file at exit (`extension/index.ts` :1134) + +On a job's `exit`, `countLogLines` reads the **entire** log in 64 KB chunks on +the main thread, just to report an `N lines` stat in the wake. With the cap in +place the file is bounded at 64 MiB — that is still a synchronous full-file read +per job exit, so the byte bound here is **required**, not defence in depth. + +Add a hard read bound (e.g. 64 MiB, or `maxLogBytes` when non-zero) and add +`fstatSync` for the tail offset: the current code derives the 512-byte pread +offset from `size` accumulated while streaming, so a *capped* `size` would seek to +the wrong place and drop the exit marker from the line-count accounting. Seek by +the real `fstatSync(fd).size` instead. + +### 2. `tailBookmarks` grows unboundedly (`extension/index.ts` :2255) + +`bgtail`'s delta-tailing bookmarks map gains one entry per distinct job id ever +tailed and is never evicted — confirmed: the map has only `.get`/`.set`, no +`.delete`/`.clear` anywhere. A slow leak over a long session. + +Evict entries in `cleanSessionJobs` (:1305) / `cleanOldJobs` (:1246) when the job's +log is removed, and/or cap the map (drop the oldest insertion) so it cannot grow +without bound. + +### 3. (context) CI runs tests on Bun only + +`.github/workflows/ci.yml` runs `npm test` → `bun test extension/index.test.ts`, +so the Node/V8 worker + regex path (:90-161) — the reason `bggrep`'s worker +bound exists — is never exercised in CI. If the ceiling work adds a +self-terminating output generator test, a Node smoke job is cheap to add then. +Not required for this feature. + +Seventh pass — **adversarial-review round: ten defects fixed, each pinned by a test** (2026-09-20): + +Every item below was reproduced before it was fixed; the test named with each is +the regression guard. Measured, not asserted: with this round's test file run +against the pre-round source (the committed `tee | head -c | cat` shape, +`e7f0669`), **14 tests fail** — every ceiling assertion re-pinned here, plus the +backgrounded-child test timing out at 4 s, which *is* the pre-fix hang. + +1. **A ceiling literal that `sh` cannot parse emptied the log.** `1e21` (and any + value above `Number.MAX_SAFE_INTEGER`) reached the wrapper as `head -c 1e+21`, + which errors and writes nothing — output discarded, not merely uncapped. Likewise a + *fractional* ceiling (`0.5`) truncated to `0`, and `0` means unlimited, so the cap + silently vanished. Fix: normalize to an integer in `1 … MAX_SAFE_INTEGER` before it + is ever interpolated into the shell. + Tests: *a ceiling above Number.MAX_SAFE_INTEGER still logs the output*, *a fractional + ceiling caps instead of silently meaning unlimited*. +2. **`mkfifo` failure ran uncapped and silently.** The fallback path now prints a + `[pi-bgrun] log ceiling unavailable …` notice and sets the marker's `nocap` flag, so + "the ceiling could not be installed" is never indistinguishable from "output was that + small". Test: *formatBytes / parseCapStatus: the cap comes from the marker, never + from printable text*. +3. **Truncation detection was inferable from printable text.** Earlier shapes asked the + log itself (`wc -l`, a sentinel line), so a command that printed a line resembling + the notice could fake a capped log — and a `head -c` + drain shape could not tell + "exactly at the cap" from "still writing" without a race. Fix: the writer's own + out-of-band state — a fifo drain that reports the byte budget and truncation, and the + flag carried in the exit marker's own line. Test: *a command that prints the notice + cannot make its log look capped*. +4. **A backgrounded child held the job open.** As a pipeline stage the wrapper waited for + pipe EOF, so a command that backgrounded a child and exited (`sleep 30 & echo done`) + produced **no wake for 30s — or never, for a daemon**; the job reported completion + after the stray. Fix: `wait` on the command's own pid, then a short bounded grace for + the drain, so completion follows the command, and output from a stray that outlives it + simply stops being logged. Test: *a backgrounded child does not hold the job open*. +5. **Fold-in #1** (`countLogLines`): resolved, see the fold-in section above. +6. **Fold-in #2** (`tailBookmarks`): resolved, see the fold-in section above. +7. **The widest window could not cover a capped log.** `bytes` was clamped to the ceiling + itself, but a capped log is always *larger* than the cap (notices + marker), so the + documented "widen it to the whole capped log" was never actually reachable. Fix: + `readWindowMax()` = ceiling + 4 KiB. Test: *readWindowMax: the widest search window + can cover a log the ceiling produced*. +8. **A window could be materialized line-by-line without bound.** Byte-bounding a window + is not enough when the lines are tiny: 64 MiB of one-character lines is ~33 M line + strings, measured at >3 GB of RSS — an OOM on exactly the log class the ceiling exists + for. Fix: `LOG_SCAN_LINES_MAX = 500_000` (~40 MB), with a labelled note ("only the + last N lines of that window were searched") so a trimmed window is never reported as a + plain "none". Test: *bgtail/bggrep: a window of very short lines is scan-bounded, and + says so*. +9. **Staging files outlived the sweep.** The sweep reclaimed marker files only, so a job + that died before its wrapper's `rm -f` left `.tmp-*.(log|ec|fifo|pid|trunc)` behind + forever — while sweeping them on mtime alone would delete a *running* job's staged + fifo out from under it. Fix: sweep by mtime **and** skip any stem whose `.pid` belongs + to a live process. Tests: *bgclean: stale staging files (.ec/.fifo/.pid/.trunc) are + reclaimed, unrelated .tmp-* are not*, *bgclean: a running job's staging files survive + an aggressive sweep*. +10. **The CI allowlist guard could pass without checking anything.** A failing + `bun pm pack` printed `? files` and the step stayed green (the later greps cannot fail + on an empty listing), so a broken tarball could ship with a green check. Fix: an + explicit `pack_status`/file-count guard. Separately, the packer under test changed to + **npm**: `release.yml` publishes with `npm publish` (OIDC trusted publishing), so the + allowlist must be checked against the packer that actually builds the shipped tarball. + Both packers emit the identical 7 files today, and that agreement is the check's + purpose. npm is preinstalled on the runner — no second toolchain. + +**Drift corrections to earlier passes:** the staging-suffix set is +`[".log", ".ec", ".fifo", ".pid", ".trunc"]` (not `.cnt`), and the wrapper's argv is +`$1` command, `$2` ecfile, `$3` fifo, `$4` pidfile, `$5` truncation-flag file. The +`tee`-into-`wc -c` prototype in the design section was replaced by the single copier +(perl first, then `dd`, then `head`) that caps, flags, and drains in one process. + +**Verified (2026-09-20):** 193/193 pass under both runners — `bun test +extension/index.test.ts` and `node --test extension/index.test.ts` (Node 24.15, ~20s), +`tsc --noEmit` clean, `npm pack --dry-run` guard exercised locally, `actionlint` clean. From 5cdce8a198a423469f5327420d1f0c9c4bfcb00b Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:28:46 -0400 Subject: [PATCH 11/13] docs: refresh the brief's status, commit list, and pass counts --- LOG-SIZE-CEILING.md | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/LOG-SIZE-CEILING.md b/LOG-SIZE-CEILING.md index e853cb2..49e0fe2 100644 --- a/LOG-SIZE-CEILING.md +++ b/LOG-SIZE-CEILING.md @@ -1,10 +1,14 @@ # bgrun: child stdout size ceiling (Option A) — implementation brief Status: IMPLEMENTED and COMMITTED on `lloydsk/log-size-ceiling`, base -`8cba8d9`. Every commit verified green on its own tree (`tsc --noEmit` + 183/183 -under bun); HEAD also verified under `node --test` (183/183). +`8cba8d9`. Every commit verified green on its own tree (`tsc --noEmit` + 193/193 +under bun); HEAD also verified under `node --test` (193/193, Node 24.15, ~20s). ``` +e72b9aa docs: add the log-size-ceiling implementation brief +e39fb13 docs: state the ceiling's reader contract (marker flag, window and line bounds) +73a8327 ci: check the publish allowlist with npm pack +8e27f03 fix: close the log-ceiling review defects (shell parsing, hang, bounds) f137a9f ci(release): document why publishing stays on npm, not bun publish 63a1c15 test: cover the bggrep sync fallback (the path without worker_threads) c2f4207 test: verify the bggrep worker abort path, and fix a vacuous pathological test From f1ebb5edd63fe22f3b2378da4ac888424948a067 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:35:23 -0400 Subject: [PATCH 12/13] docs: track the ceiling rationale in docs/, and fix the notice literals MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The brief at the repo root was a process artifact — status line, commit list, time estimate, "re-verified against " — exactly the content that rots once it is tracked. Its substance now lives in docs/log-size-ceiling.md: the problem and the five constraints, the shipped fifo/copier shape with each load-bearing oddity explained, the measurement table that rules out the cheap truncation detectors, the visible-and-unforgeable contract, reader bounds, config normalization, the defects already paid for, and the rejected alternatives. docs/ is the home for design notes of this kind from here on. Also fix what the docs claimed the truncation notice looks like. README and the run-bg skill promised `[pi-bgrun] output truncated at bytes (first bytes kept)`; the wrapper has never printed that. The shipped lines are `__BGRUN_TRUNC__ output truncated: kept the first bytes` and, when the ceiling could not be installed, `__BGRUN_NOCAP__ log ceiling unavailable`. Both are reserved `__BGRUN_*__` lines, identified by the marker's flag rather than by matching text — an agent following the skill was looking for a string that does not exist. And describe both wrapper paths in "How it works", which still showed only the uncapped one-liner. --- LOG-SIZE-CEILING.md | 563 --------------------------------------- README.md | 24 +- docs/log-size-ceiling.md | 196 ++++++++++++++ skill/run-bg/SKILL.md | 10 +- 4 files changed, 219 insertions(+), 574 deletions(-) delete mode 100644 LOG-SIZE-CEILING.md create mode 100644 docs/log-size-ceiling.md diff --git a/LOG-SIZE-CEILING.md b/LOG-SIZE-CEILING.md deleted file mode 100644 index 49e0fe2..0000000 --- a/LOG-SIZE-CEILING.md +++ /dev/null @@ -1,563 +0,0 @@ -# bgrun: child stdout size ceiling (Option A) — implementation brief - -Status: IMPLEMENTED and COMMITTED on `lloydsk/log-size-ceiling`, base -`8cba8d9`. Every commit verified green on its own tree (`tsc --noEmit` + 193/193 -under bun); HEAD also verified under `node --test` (193/193, Node 24.15, ~20s). - -``` -e72b9aa docs: add the log-size-ceiling implementation brief -e39fb13 docs: state the ceiling's reader contract (marker flag, window and line bounds) -73a8327 ci: check the publish allowlist with npm pack -8e27f03 fix: close the log-ceiling review defects (shell parsing, hang, bounds) -f137a9f ci(release): document why publishing stays on npm, not bun publish -63a1c15 test: cover the bggrep sync fallback (the path without worker_threads) -c2f4207 test: verify the bggrep worker abort path, and fix a vacuous pathological test -1dcf365 ci: run everything on bun, drop the Node toolchain -311cd48 docs: deprecate the machine-global jobs dir; resolve home consistently -e7f0669 feat: cap background job log output, and make readers honest about it -``` - -Feature diff: `extension/index.ts`, `extension/index.test.ts`, `README.md`, -`skill/run-bg/SKILL.md` (+1178/−89 across the three commits, plus the CI file). -This brief is untracked — it is the PR body, not a shipped artifact. - -Deviations from the design below, decided during implementation: - -- The cap value is baked into the generated wrapper script rather than passed as - argv; argv is now `$1` command, `$2` ecfile, `$3` fifo, `$4` countfile. -- If `mkfifo` fails, the wrapper falls back to the **uncapped** path — losing - output is worse than losing the ceiling. -- `countLogLines` returns `null` (line stat omitted) rather than a partial count - when the log exceeds its 64 MiB scan bound, and reads the tail offset from - `fstatSync`. It also returns `null` if the file's size changes mid-scan. -- `tailBookmarks` is declared next to `jobs` (so cleanup can evict it without a - TDZ hazard) and additionally bounded by `TAIL_BOOKMARK_CAP = 1000` via a - `rememberTail()` helper, because cleanup only evicts jobs whose log it removed. -- The staging-suffix set is `STAGING_SUFFIXES = [".log", ".ec", ".fifo", ".cnt"]`. -- Two pre-existing issues surfaced while verifying: this worktree had drifted - `@types/node` 26.4.1 (spec `^24.0.0`), which made the pristine base fail - `tsc --noEmit` — fixed with `bun install --frozen-lockfile` (now 24.13.5), not - by changing source. And the wake-stats test pinned `Stats: 0.0s` for an - instant job; the capped wrapper spawns a few extra processes, so it is now - asserted by shape (`/Stats: \d+\.\d+s, 1 lines/`) instead of pinning the host. -- Tests written: cap+notice+head-kept+exit-code, notice-excluded-from-stats and - from last-line, exact-cap boundary, `0` = uncapped, no staging strays, stale - staging reclaimed by the sweep (unrelated `.tmp-*` kept), bgtail/bggrep on a - capped log plus the post-cap bytes being unsearchable, a multi-megabyte flood - still exiting with its own code (no SIGPIPE), and `resolveConfig` normalization - (blank env must not disable the cap). - -Follow-on (added 2026-09-20, second pass): **truncation is agent-visible**, not -just on disk. The first pass filtered the notice out of every reader, which meant -nothing told the agent a log had been capped — and the shipped digest presets -(jest/pytest/go-test/junit-xml all read the log's END) would then report -`fail: 0` for a run whose failures were past the cap. Now: - -- `parseTruncationFromContent()` (exact: the notice counts only when it is the - line immediately before the exit marker) + `readTruncationBytes()` (decided - from the standard 256 KB tail slice — no extra IO) + `formatBytes()`. -- The wake's Stats line gains `log truncated at 64 MiB`. -- A selected digest is **skipped** with an explanation instead of run. -- `bgtail`/`bggrep` append a labelled note and report `truncatedAtBytes` in - their details (`bgtail` also on its delta early-return path). -- README + `skill/run-bg/SKILL.md` state the rule: on a capped job, a missing - digest means "unknown", not "no failures". -- Context cost: zero for under-cap jobs; for capped jobs one extra clause in the - Stats line and one note line per reader call (the alternative — a confidently - wrong scorecard — costs more and misleads). - -Follow-on (added 2026-09-20, third pass): **context economics vs context-mode**, -measured on a synthetic 1.29 MB / 20 000-line test log (raw ≈ 1.29 MB): - -| path | context cost | -| --- | --- | -| raw dump | 1,287,215 chars | -| wake alone (exit, duration, lines, last line, digest, truncation) | ~200 chars | -| `bgtail` (last 40, condensed, 8 KB cap) | 2,600 chars | -| `bggrep` (failure regex, ≤50 matches) | 873 chars | -| `ctx_execute_file` equivalent | 744 chars stdout **+ 221 chars of code the model writes** | - -Output envelopes are comparable, so the read tools do not win on bytes; they win -on zero-code calls, in-memory delta bookmarks (repeat polls ~free), job-id -resolution, a regex wall-clock budget, and no FTS5 side effects (`ctx_execute_file` -auto-indexes stdout >100 KB and switches to BM25 sections above 5 KB with `intent`). -The wake is the real saver — most jobs need no read at all. - -Two defects found while checking, both fixed: - -1. The claim that a "project-sandboxed `ctx_execute_file` cannot reach the global - jobs dir" was **false** — its schema takes "absolute file path or relative to - project root" and its only check is the agent's own Read-deny policy - (`checkFilePathDenyPolicy`); there is no project-root confinement. Corrected in - README (×3), `skill/run-bg/SKILL.md` (×2) and bggrep's tool description, and - reframed: the real advantage is resolving the job id, not reach. -2. `bgtail`/`bggrep` read only the **last 2 MB** (`LOG_READ_BYTES`, one call site - in `resolveLogForJob`) — with a 64 MiB ceiling that silently hides 97% of a - capped log, and "— none" reads as "no failures anywhere". Both readers now - append a window caveat when `size > LOG_READ_BYTES`, and the SKILL points at - `ctx_execute_file` as the whole-file path (the only tool that covers >2 MB). - -Third pass, part 2 — the window became an argument (this was the user's read on -defect 2, and it was right): - -- **The two bounds are independent, which the first pass blurred.** `maxLogBytes` - bounds bytes *written to disk* (inside the detached wrapper); `LOG_READ_BYTES` - bounds bytes *scanned* by the readers (`resolveLogForJob`). The cap never - bounded reads — past 2 MB the readers always saw a slice, and a legitimate - 64 MiB log made that slice 3% of the file. -- **`bytes` param on `bgtail` and `bggrep`**, clamped by `clampReadWindow()`: - absent/garbage/≤0 → the 2 MiB default; wider than `LOG_READ_BYTES_MAX` - (= `DEFAULT_MAX_LOG_BYTES`, since no job can have written more than the - ceiling) → the ceiling. Both report `windowBytes` in details. -- **A wide window costs latency and memory, NOT context.** Only the scan grows; - the returned text stays capped by the condenser (~8 KB, ≤50 matches). Asserted - directly: an 8 MiB-window search over a 2.7 MB log finds a marker the default - window misses while the result stays <9000 chars. -- **Bug caught while wiring it:** a changed window moves the window's *first* - line, so the stale "log was replaced" heuristic fired first and mislabelled a - widened read. `windowChanged` now beats `replaced`, and bgtail resets the delta - with `search window changed since last read — showing full tail` instead of - reporting pages of "new" lines that were merely never looked at. -- The window caveat now names the actual window and the escape hatch: `pass a - larger 'bytes' (max 64 MiB) or use ctx_execute_file on the log path`. - -Third pass, part 3 — **the machine-global jobs dir is deprecated** (user call, -docs-only, staged): - -- Project-scoped logs are the model; `PI_BGRUN_GLOBAL_DIR` and the - `~/.pi-bgrun/jobs` destination are marked deprecated in the README env table, - the Roadmap, and the run-bg SKILL, with a new `### Deprecated: machine-global - jobs dir` section (why project-scoped won, what is lost, 3-step migration). -- **Nothing breaks today:** existing absolute `jobsDir`/`PI_BGRUN_DIR` behave - exactly as before; removal is reserved for a future major. -- **The fallback cannot be removed, only demoted:** a cwd with no project root - still resolves to `~/.pi-bgrun/jobs` (`globalJobsDir()` at :733/:735). The - alternative is scattering logs into an arbitrary cwd, which the code - deliberately refuses. It becomes an undocumented internal fallback. -- **`PI_BGRUN_GLOBAL_DIR` is also the test seam** (`index.test.ts:75`, plus two - more sites) for staying off the real `~/.pi-bgrun`, so "remove the knob" needs - a HOME-override replacement in the same change. -- **No runtime deprecation warning, deliberately:** it would fire on every - test-run config and cannot distinguish a test seam from a real user. Docs are - the honest lever; add the warning on request. - -Fourth pass — **Node leaves CI, and the seam stops being the deprecated knob**: - -- **`bun pm pack --dry-run` is a real substitute** for `npm pack --dry-run` (it - prints the packed file list and `Total files: N`), and `bunx`/`bun run lint` - cover `npx tsc`. So every CI step ran on Bun already, with a Node toolchain - installed for nothing. `ci.yml` is now **bun-only**: no `setup-node`, steps are - `bun install --frozen-lockfile` / `bun run lint` / `bun test - extension/index.test.ts` / `bun pm pack --dry-run` (guard re-pointed at Bun's - `Total files:` casing). All four verified locally, including the tarball - allowlist guard parsing 7 files and rejecting test-file patterns. -- **What dropping Node costs:** the V8/worker_threads side of bggrep's bounded - matching is no longer exercised in CI. Bun *does* implement - `node:worker_threads` (verified: `typeof Worker === "function"`), so the worker - *mechanism* is still covered — only V8's backtracking behaviour is not. Manual - insurance, recorded in a comment in `ci.yml`: `node --test - extension/index.test.ts` passes **183/183 in ~16s** (run 2026-09-20, Node - 24.15). Re-run it by hand after touching the worker path. -- **`fold-in #3` is therefore resolved as "no Node job"**, not deferred. -- **The test seam no longer rides on the deprecated knob.** `PI_BGRUN_GLOBAL_DIR` - was the only way to keep tests off the real `~/.pi-bgrun`, because **Bun's - `os.homedir()` ignores `$HOME`** (verified: unchanged after mutating HOME in - process) — the old-looking `homeDir()`-style comment in `resolveConfig` was the - maintainers working around exactly that. Fix: a `homeDir()` helper that is - HOME-first (`process.env.HOME || homedir()`), used by `globalJobsDir()`, - `expandTilde()`, `findProjectRoot()` and the user-config path. Node already - behaved this way, so this *aligns* the runtimes rather than inventing policy; - the test file now pins `HOME` and leaves `PI_BGRUN_GLOBAL_DIR` unset, so - retiring the knob is a docs+3-line delete instead of a test rewrite. - Verified green under **both** runners (183/183 bun, 183/183 node). -- `PI_BGRUN_GLOBAL_DIR` stays *supported* (deprecated) — the deprecation is about - the machine-global destination, not about this override, which is also the - escape hatch for anyone who genuinely wants one shared dir. - -Fifth pass — **the V8 concern, measured, and a vacuous test fixed**: - -| engine | `^(a+)+$` over `"a"×n + "!"` | | -| --- | --- | --- | -| Node 24.15 (V8/Irregexp) | n=100 → **killed at 10s** | exponential backtracking | -| Bun 1.3.6 (JSC) | n=100…5000 → **~250ms, constant** | no backtracking blowup | - -So the hazard the worker+budget exists for is real and *engine-specific*: on -JSC the pathological case effectively does not exist, which is why a Bun-only CI -cannot verify the guard by input. Two things follow: - -1. **The shipped test was vacuous.** `bggrep: a pathological regex returns within - the budget instead of hanging` wrote 60 000 "a"s plus a "b" — but bggrep - pre-truncates each line to `BGGREP_LINE_CAP = 10 000` *before* matching, so - the "b" was cut away and `^(a+)+$` matched in **0ms on both engines**. The - failing character now sits inside the cap window: 2004ms on Node (budget - trips, worker terminated), ~250ms on Bun. -2. **The abort path now has an engine-independent test.** - `matchLinesWithBudget()` takes an injectable worker body (optional param, - defaulting to `BGGREP_WORKER_SOURCE`) and is exported for tests, so a worker - that never returns proves the budget ends it — ~300ms, on both engines. - That is the assertion an input-driven pattern cannot make portably. - -3. **The sync fallback is covered too.** `matchLinesSyncBounded` runs only where - `node:worker_threads` is missing — never on Node or Bun — so nothing exercised - it: a regression there would ship silently and surface as "bggrep behaves - differently in that environment". Exported for tests (like the other seams) - and covered by parity with the worker path (matches, misses, the per-line cap, - a bad pattern's `invalid` outcome) plus both budget guards: fired before the - first line when the budget is already spent, and re-checked mid-scan (0 ms - budget over 300 000 lines aborts rather than finishing the corpus). - -Sixth pass — **publishing stays on npm** (asked: any downside to `bun publish`?). -`bun publish` has no OIDC trusted-publishing and no provenance support (auth is a -long-lived `NPM_CONFIG_TOKEN`; the documented flags carry no provenance option), -while `release.yml` relies on `id-token: write`, stores **no** token, and gets -provenance attestations for free from trusted publishing. Switching would trade a -tokenless, attested release for a stored bearer credential — so the release path -keeps Node+npm deliberately, unlike the test job, and a comment next to the Node -setup says why. Functional parity was *not* the issue: `--access`, `--tag`, -`--dry-run`, `--otp` and registry config all exist in Bun, lifecycle-script -differences are moot (no `prepack`/`prepublishOnly`/`prepare` here), and -`--tolerate-republish` is actually nicer than npm for CI re-runs. - -Consequence for the CI decision: `bun test` now covers the worker *mechanism* -deterministically (abort path + budget plumbing + the fixed stress input) and -the fallback's contract, and `node --test` remains the only way to exercise V8's -own backtracking — a manual command, noted in `ci.yml`. Suite: 186/186 under -both runners. - -## Problem - -`bgrun` redirects the child's stdout+stderr straight to the log fd -(`spawn("sh", ["-c", wrapper, "bgrun", command], { stdio: ["ignore", logFd, logFd], detached: true })`, -`extension/index.ts` ~:1765). The read side is bounded on this base -(`readLogSlice()` @:221 — `LOG_TAIL_BYTES = 256 KB` for the exit marker, -`LOG_READ_BYTES = 2 MB` for `bgtail`/`bggrep`), but the **write side is -unbounded**: a runaway job (`yes`, a spew loop, a pathological build) fills the -disk and can take the machine down. Secondary effect: `countLogLines` (:1134) -streams the whole file at exit (bounded memory, unbounded IO). - -## Constraints (any fix must respect these) - -1. The cap must live **inside the detached process tree** — pi can exit at any - time. No parent-side streaming (that would break "survives pi crashing"). -2. The `__BGRUN_EXIT__` marker must remain the **last non-empty line** — - `parseExitFromContent` (:256) walks backwards to the last non-blank line and - treats only that as completion evidence (a marker that is not last is job - output that happens to contain the string). `readLogSlice(LOG_TAIL_BYTES)` - finds it as long as it stays in the final 256 KB — which a head cap - guarantees, since the whole capped log is ≤ CAP + overhead. -3. One writer, one offset — two writers into the same file corrupt it (this - includes the exit-code file; see below). -4. Cap only the redirected stdout/stderr, **never the command's own files**. -5. `maxLogBytes: 0` means unlimited and MUST produce the **current** wrapper - verbatim. It must not be routed through the capped pipeline. - -## Chosen design: Option A — in-tree head cap, job survives - -Replace the current wrapper: - -```sh -sh -c "$1"; ec=$?; printf '\n__BGRUN_EXIT__%d\n' "$ec"; exit "$ec" -``` - -with a capped pipeline plus an exact byte counter: - -```sh -# argv: $1 = command, $2 = ecfile, $3 = cap, $4 = fifo, $5 = countfile -count="$5"; rm -f "$4" "$count"; mkfifo "$4"; ( wc -c <"$4" >"$count" ) & ctr=$! -{ sh -c "$1" 2>&1; ec=$?; printf '%d' "$ec" >"$2"; } \ - | tee "$4" | { head -c "$3"; cat >/dev/null; } -wait "$ctr" -total=$(cat "$count"); ec=$(cat "$2") -rm -f "$2" "$4" "$count" -if [ "${total:-0}" -gt "$3" ]; then - printf '\n[pi-bgrun] output truncated at %s bytes (first %s bytes kept)\n' \ - "$3" "$3" -fi -printf '\n__BGRUN_EXIT__%d\n' "$ec"; exit "$ec" -``` - -(The notice literal above is generated from `TRUNC_NOTICE_PREFIX`; it is a -constant, so it is safe to interpolate into the wrapper's format string.) - -Why this shape: - -- `head -c CAP` writes the first CAP bytes to the wrapper's stdout (the log fd). -- `cat >/dev/null` then drains the rest, so the producer never gets SIGPIPE and - the **job runs to completion** with its real exit code (unlike Option B). -- `tee "$fifo"` runs a *second*, uncapped copy of the stream into `wc -c`, so - the wrapper knows the true total. `total > CAP` is the truncation test. -- The command's exit status is captured to `$2` *by the producer group* - (redirected to a file, not the pipe), because a pipeline's `$?` is the - reader's. The wrapper reads `$2` and prints the marker. Constraint 3 holds: - only the producer writes `$2`, only `wc` writes `$5`. -- Single writer at a time into the log: the reader stage writes to fd1, then the - wrapper's `printf` writes to the same fd1 — same offset, no corruption. -- Works with pi dead: the whole thing is inside the detached tree. - -Accepted price: the log keeps the **first** CAP bytes, not the tail. There is no -portable in-tree *tail* cap — a ring buffer needs a helper binary, and a circular -file breaks every existing reader (marker-at-tail, `bgtail`, `bggrep`). A job -that emits > CAP is almost always a runaway, so the head is the useful part. - -### Truncation detection: why not the simple counters - -Measured on this machine (macOS 25.6, BSD `head`) while writing this brief: - -| detection idea | result | -| --- | --- | -| count bytes left after `head -c CAP` (`cat \| wc -c`) | **silently 0** whenever the overshoot is smaller than `head`'s read buffer: `CAP=100 N=101` → 0, `CAP=1000 N=1500` → 0, `CAP=8192 N=8193` → 0; only `CAP=65536 N=65537` → 1. `head` over-reads into its buffer and discards the excess. | -| `wc -c cap`, append: - -``` -[pi-bgrun] output truncated at bytes (first bytes kept) -``` - -Details that matter: - -- **Leading `\n` is required.** Without it the notice glues onto the truncated - last byte (`…aaa[pi-bgrun] output truncated…`), which corrupts line counts and - `bggrep` line numbers. Verified in the prototype. -- Define one constant (`TRUNC_NOTICE_PREFIX = "[pi-bgrun] output truncated"`) and - filter it wherever `EXIT_MARKER` is filtered today: `countLogLines`' tail - accounting ("N lines" must not count the notice) and the wake's last-line - pick. Otherwise the wake reports the notice as the job's last output. -- `bggrep` will match the notice if the caller greps that phrase (e.g. grepping - a bgrun log for `truncated`). That is acceptable and should be documented in - `skill/run-bg/SKILL.md` rather than worked around. - -## Config + env - -- New config field `maxLogBytes` (number, bytes), plus `PI_BGRUN_MAX_LOG_BYTES`. -- Default **64 MiB**. `0` = unlimited (documented escape hatch) → take the - legacy uncapped wrapper path, no fifo, no reader. -- Read at spawn time (per-job), so a config edit affects the next job only. -- Validate like the other numeric fields: finite, integer, `>= 0`; reject `NaN` - / negative / non-number to the default. - -## Files / plumbing - -- `extension/index.ts`: - - config field + normalization + env merge (next to `cleanupDays`, :950-1003). - - wrapper construction + spawn argv in the `bgrun` tool `execute` (~:1750). - The wrapper already receives `command` as `$1`; add `$2` ecfile, `$3` cap, - `$4` fifo, `$5` countfile. - - `TRUNC_NOTICE_PREFIX`, and the marker-filtering updates in - `countLogLines` (:1134) and the last-line pick. - - help/description text. -- Staging artifacts, next to the log in the jobs dir (same convention as the - existing `.tmp---.log`): `.tmp---.ec`, - `…fifo`, `…cnt`. The jobs dir is guaranteed writable (the log fd already lives - there), unlike `TMPDIR`. -- **Widen the sweep predicate.** `sweepStaleMarkers` (:1220) currently reclaims - only `.tmp-*` names ending in `.log`; the new `.ec`/`.fifo`/`.cnt` strays - (left only by a hard kill) would never be reclaimed. Match - `.tmp-*.(log|ec|fifo|cnt)`. Do **not** rename the ec file to `.log` to reuse - the existing predicate: `.log`-suffixed files are treated as job logs by - `adoptForeignJobs` / `cleanOldJobs` / `bgstatus`, and the `.tmp-` skip exists - only in one function (:346). -- In the normal path the wrapper removes its own artifacts (verified); the sweep - is for kill -9 / power loss only. -- `README.md`: env-table row + a short "Log size ceiling" note (state the - head-cap tradeoff explicitly). -- `skill/run-bg/SKILL.md`: one line so the agent knows logs can be truncated and - the notice line is not command output. - -## Tests - -The list below is the acceptance sketch from planning. What actually shipped is -these 18 tests (the earlier 165 are unchanged and pass against the capped -wrapper, which is the transparency check for bgtail/bggrep/digest/adopt): - -| # | Test | -| --- | --- | -| 1 | maxLogBytes keeps the first N bytes, notes the truncation, preserves the exit code | -| 2 | the truncation notice is not job output — not counted, not the last line | -| 3 | a job that outruns the cap by megabytes still finishes with its own exit code (no SIGPIPE) | -| 4 | a log at exactly the cap is not called truncated; one byte over is | -| 5 | maxLogBytes 0 leaves the log uncapped | -| 6 | a capped job leaves no staging files behind | -| 7 | stale staging files (.ec/.fifo/.cnt) are reclaimed; unrelated `.tmp-*` are not | -| 8 | bgtail/bggrep work on a capped log and only see what was kept | -| 9 | resolveConfig: maxLogBytes accepts 0 and ignores blank/invalid values | -| 10 | formatBytes / parseTruncationFromContent: the notice counts only as the wrapper's own line | -| 11 | wake: a capped job says so in the Stats line; an uncapped one does not | -| 12 | wake digest: a scorecard is skipped, not misreported, when the log was capped | -| 13 | bgtail/bggrep: a capped log is labelled and carries truncatedAtBytes | -| 14 | bgtail/bggrep: no truncation label on an uncapped log | -| 15 | a log bigger than the 2 MB read window says it was only partly searched | -| 16 | no window caveat on a small log | -| 17 | `bytes` widens the search window without widening the output | -| 18 | clampReadWindow: default, explicit, garbage, and ceiling | - -Original sketch below. - -1. Generator > CAP → log size is exactly `CAP + notice + marker + leading - newlines` (not merely "≤ CAP + overhead" — pin the real ceiling), marker - present and last, exit code correct. -2. Truncation notice present when capped; absent when under; **exact-CAP output - is not reported as truncated** (boundary). -3. Exit code preserved exactly (0 and non-zero) through the pipeline. -4. Notice is not counted by `countLogLines` and is not the wake's last line. -5. `bgtail`/`bggrep` on a capped log: content returned, marker found, and - `readLogSlice`'s `truncated: true` (tail window < file) is asserted as a - *distinct* signal from the cap notice — do not conflate them. -6. `maxLogBytes: 0` disables the cap (full output written, no notice, no fifo - created, legacy wrapper path used). -7. `$ecfile`/fifo/countfile removed after use (no stray `.tmp-*` beyond the - log); a simulated stale one is reclaimed by `sweepStaleMarkers`. -8. Existing behavior unchanged: pipes, `&&`, `#`, quotes, heredoc commands. -9. Notice has a leading newline — assert the byte before the notice is `\n`. - -## Rejected alternatives - -- **C — pi-side watchdog** (stat running logs, kill + truncate tail): soft bound - only while pi lives; overshoot = write-rate × poll interval; unbounded if pi - died. Keeps the tail, but doesn't keep the promise. -- **B — `head -c` without the `cat` drain**: producer dies on SIGPIPE (141); - hostile to legitimately verbose builds. -- **D — `ulimit -f`**: caps *every* file the job writes (artifacts, downloads) - and kills it (SIGXFSZ/153). Opt-in only, not a default. -- **E — document + trim finished logs**: no bound while running. -- **F — `dd bs=1 count=CAP`** as an exact front stage: no over-read, but one - read syscall per byte (64 MiB cap = 64M syscalls) — unusable. - -Revisit C only if tail retention turns out to matter in practice. - -Estimate: ~2.5–3 h including tests and the two fold-ins below (the earlier ~1.5 h -estimate predated the detector rework, the `0` branch, and reconciliation with -PR #11 — the rebase itself is now done). - -## Fold-in follow-ups (from the 2026-09 adversarial review) - -**Status (2026-09-20): both closed, see the seventh pass.** -**#1** closed — `countLogLines` now takes the tail offset from `fstatSync(fd).size` -and refuses (returns `null`) when the file exceeds `readWindowMax()`, so the scan -is bounded and the tail pread can never be misplaced by a bound. -**#2** closed — the map is evicted on log removal (`cleanOldJobs`, -`cleanSessionJobs`) *and* hard-capped by `TAIL_BOOKMARK_CAP` with -oldest-insertion eviction, so it cannot grow unboundedly even without cleanup. -**#3** resolved as "no Node job" (fourth pass, fourth bullet), not deferred. - -Both were found on the review branch (`lloydsk/Feedback-Improvements`, PR #11) -and deliberately deferred here, because a log size ceiling is the proper fix for -both — do them as part of this work, not separately. Re-verified against -`8cba8d9`: both were still open. - -### 1. `countLogLines` streams the whole file at exit (`extension/index.ts` :1134) - -On a job's `exit`, `countLogLines` reads the **entire** log in 64 KB chunks on -the main thread, just to report an `N lines` stat in the wake. With the cap in -place the file is bounded at 64 MiB — that is still a synchronous full-file read -per job exit, so the byte bound here is **required**, not defence in depth. - -Add a hard read bound (e.g. 64 MiB, or `maxLogBytes` when non-zero) and add -`fstatSync` for the tail offset: the current code derives the 512-byte pread -offset from `size` accumulated while streaming, so a *capped* `size` would seek to -the wrong place and drop the exit marker from the line-count accounting. Seek by -the real `fstatSync(fd).size` instead. - -### 2. `tailBookmarks` grows unboundedly (`extension/index.ts` :2255) - -`bgtail`'s delta-tailing bookmarks map gains one entry per distinct job id ever -tailed and is never evicted — confirmed: the map has only `.get`/`.set`, no -`.delete`/`.clear` anywhere. A slow leak over a long session. - -Evict entries in `cleanSessionJobs` (:1305) / `cleanOldJobs` (:1246) when the job's -log is removed, and/or cap the map (drop the oldest insertion) so it cannot grow -without bound. - -### 3. (context) CI runs tests on Bun only - -`.github/workflows/ci.yml` runs `npm test` → `bun test extension/index.test.ts`, -so the Node/V8 worker + regex path (:90-161) — the reason `bggrep`'s worker -bound exists — is never exercised in CI. If the ceiling work adds a -self-terminating output generator test, a Node smoke job is cheap to add then. -Not required for this feature. - -Seventh pass — **adversarial-review round: ten defects fixed, each pinned by a test** (2026-09-20): - -Every item below was reproduced before it was fixed; the test named with each is -the regression guard. Measured, not asserted: with this round's test file run -against the pre-round source (the committed `tee | head -c | cat` shape, -`e7f0669`), **14 tests fail** — every ceiling assertion re-pinned here, plus the -backgrounded-child test timing out at 4 s, which *is* the pre-fix hang. - -1. **A ceiling literal that `sh` cannot parse emptied the log.** `1e21` (and any - value above `Number.MAX_SAFE_INTEGER`) reached the wrapper as `head -c 1e+21`, - which errors and writes nothing — output discarded, not merely uncapped. Likewise a - *fractional* ceiling (`0.5`) truncated to `0`, and `0` means unlimited, so the cap - silently vanished. Fix: normalize to an integer in `1 … MAX_SAFE_INTEGER` before it - is ever interpolated into the shell. - Tests: *a ceiling above Number.MAX_SAFE_INTEGER still logs the output*, *a fractional - ceiling caps instead of silently meaning unlimited*. -2. **`mkfifo` failure ran uncapped and silently.** The fallback path now prints a - `[pi-bgrun] log ceiling unavailable …` notice and sets the marker's `nocap` flag, so - "the ceiling could not be installed" is never indistinguishable from "output was that - small". Test: *formatBytes / parseCapStatus: the cap comes from the marker, never - from printable text*. -3. **Truncation detection was inferable from printable text.** Earlier shapes asked the - log itself (`wc -l`, a sentinel line), so a command that printed a line resembling - the notice could fake a capped log — and a `head -c` + drain shape could not tell - "exactly at the cap" from "still writing" without a race. Fix: the writer's own - out-of-band state — a fifo drain that reports the byte budget and truncation, and the - flag carried in the exit marker's own line. Test: *a command that prints the notice - cannot make its log look capped*. -4. **A backgrounded child held the job open.** As a pipeline stage the wrapper waited for - pipe EOF, so a command that backgrounded a child and exited (`sleep 30 & echo done`) - produced **no wake for 30s — or never, for a daemon**; the job reported completion - after the stray. Fix: `wait` on the command's own pid, then a short bounded grace for - the drain, so completion follows the command, and output from a stray that outlives it - simply stops being logged. Test: *a backgrounded child does not hold the job open*. -5. **Fold-in #1** (`countLogLines`): resolved, see the fold-in section above. -6. **Fold-in #2** (`tailBookmarks`): resolved, see the fold-in section above. -7. **The widest window could not cover a capped log.** `bytes` was clamped to the ceiling - itself, but a capped log is always *larger* than the cap (notices + marker), so the - documented "widen it to the whole capped log" was never actually reachable. Fix: - `readWindowMax()` = ceiling + 4 KiB. Test: *readWindowMax: the widest search window - can cover a log the ceiling produced*. -8. **A window could be materialized line-by-line without bound.** Byte-bounding a window - is not enough when the lines are tiny: 64 MiB of one-character lines is ~33 M line - strings, measured at >3 GB of RSS — an OOM on exactly the log class the ceiling exists - for. Fix: `LOG_SCAN_LINES_MAX = 500_000` (~40 MB), with a labelled note ("only the - last N lines of that window were searched") so a trimmed window is never reported as a - plain "none". Test: *bgtail/bggrep: a window of very short lines is scan-bounded, and - says so*. -9. **Staging files outlived the sweep.** The sweep reclaimed marker files only, so a job - that died before its wrapper's `rm -f` left `.tmp-*.(log|ec|fifo|pid|trunc)` behind - forever — while sweeping them on mtime alone would delete a *running* job's staged - fifo out from under it. Fix: sweep by mtime **and** skip any stem whose `.pid` belongs - to a live process. Tests: *bgclean: stale staging files (.ec/.fifo/.pid/.trunc) are - reclaimed, unrelated .tmp-* are not*, *bgclean: a running job's staging files survive - an aggressive sweep*. -10. **The CI allowlist guard could pass without checking anything.** A failing - `bun pm pack` printed `? files` and the step stayed green (the later greps cannot fail - on an empty listing), so a broken tarball could ship with a green check. Fix: an - explicit `pack_status`/file-count guard. Separately, the packer under test changed to - **npm**: `release.yml` publishes with `npm publish` (OIDC trusted publishing), so the - allowlist must be checked against the packer that actually builds the shipped tarball. - Both packers emit the identical 7 files today, and that agreement is the check's - purpose. npm is preinstalled on the runner — no second toolchain. - -**Drift corrections to earlier passes:** the staging-suffix set is -`[".log", ".ec", ".fifo", ".pid", ".trunc"]` (not `.cnt`), and the wrapper's argv is -`$1` command, `$2` ecfile, `$3` fifo, `$4` pidfile, `$5` truncation-flag file. The -`tee`-into-`wc -c` prototype in the design section was replaced by the single copier -(perl first, then `dd`, then `head`) that caps, flags, and drains in one process. - -**Verified (2026-09-20):** 193/193 pass under both runners — `bun test -extension/index.test.ts` and `node --test extension/index.test.ts` (Node 24.15, ~20s), -`tsc --noEmit` clean, `npm pack --dry-run` guard exercised locally, `actionlint` clean. diff --git a/README.md b/README.md index 55d6aca..f84087f 100644 --- a/README.md +++ b/README.md @@ -66,8 +66,11 @@ wake messages) is the agent's workflow. ```text agent calls bgrun(command: "make test-short", name: "unit-tests") → extension resolves log path: /--.log (default /.pi-bgrun/jobs/ in a repo, else ~/.pi-bgrun/jobs/) - → spawn('sh', ['-c', 'sh -c "$1"; ec=$?; printf "\\n__BGRUN_EXIT__=%d\\n" "$ec"; exit "$ec"', 'bgrun', ''], + → spawn('sh', ['-c', , 'bgrun', ''], { stdio: ['ignore', logFd, logFd], detached: true }).unref() + = the output-ceiling pipeline (see "Log size ceiling"), or the + uncapped one-liner 'sh -c "$1"; ec=$?; printf "\\n__BGRUN_EXIT__=%d\\n" "$ec"; exit "$ec"' + when the ceiling is disabled (maxLogBytes: 0) → records job in-memory + appends a bgrun-job entry to the session → returns "started: " @@ -147,13 +150,18 @@ default **64 MiB**, `0` = unlimited): - The job is **not** killed, and its real exit code is preserved: bytes past the cap are drained and discarded instead of SIGPIPE'ing the producer into `141`. - It is **not silent**. The log carries - `[pi-bgrun] output truncated at bytes (first bytes kept)` on the line + `__BGRUN_TRUNC__ output truncated: kept the first bytes` on the line before the exit marker, and the marker line itself carries the flag - (`__BGRUN_EXIT__=0 truncated=67108864`) — readers trust that marker, never - printable text, so a command that echoes something that looks like the notice - cannot make its own log look capped. The notice is filtered out of content - readers exactly like the exit marker, and every surface the agent reads is - labelled instead: the wake's Stats line gains `log truncated at 64 MiB`, + (`__BGRUN_EXIT__=0 truncated=67108864`). Both are reserved `__BGRUN_*__` lines + that content readers filter exactly like the exit marker, and readers classify + the notice by that **marker flag**, never by matching text — a command that + echoes a notice-shaped line cannot make its own log look capped, and cannot + get its own output discounted as wrapper bookkeeping either. If the ceiling + could not be installed at all (`mkfifo` unavailable, so the job ran uncapped) + the log says that too — `__BGRUN_NOCAP__ log ceiling unavailable`, with + `nocap=1` in the marker — so "uncapped" is never indistinguishable from + "output was that small". Every surface the agent reads is labelled: the wake's + Stats line gains `log truncated at 64 MiB`, `bgtail` and `bggrep` append a note and report `truncatedAtBytes` in their details, and a configured digest scorecard is **skipped** rather than run against a log that lost its end — summaries and failure lists live at the end, @@ -166,6 +174,8 @@ default **64 MiB**, `0` = unlimited): materializing a 64 MiB window of one-character lines would cost gigabytes of strings — and when that line bound trims a window, `bgtail`/`bggrep` say so in the same labelled way instead of silently answering from a subset. +- Maintainer rationale — why a fifo, why the *first* bytes, which alternatives + were measured and rejected: [`docs/log-size-ceiling.md`](docs/log-size-ceiling.md). - Cost: a capped job runs through one copier process (`perl` where available, else `dd`/`head`) reading the job through a fifo, plus a bounded drain wait — a few tens of milliseconds of job startup, no steady-state overhead. The diff --git a/docs/log-size-ceiling.md b/docs/log-size-ceiling.md new file mode 100644 index 0000000..89de06b --- /dev/null +++ b/docs/log-size-ceiling.md @@ -0,0 +1,196 @@ +# Child stdout ceiling: design rationale + +`maxLogBytes` / `PI_BGRUN_MAX_LOG_BYTES` bounds how much of a job's +stdout+stderr reaches its log file. The operator-facing contract is in the +README ([Log size ceiling](../README.md#log-size-ceiling)); this note is the +rationale a maintainer needs *before* changing the wrapper, and the record of +what was measured and rejected. + +## Problem + +The child's stdout+stderr go straight to the log fd +(`spawn("sh", ["-c", wrapper, "bgrun", command], { stdio: ["ignore", logFd, logFd], detached: true })`). +The read side is bounded (`LOG_TAIL_BYTES` for the exit marker, `LOG_READ_BYTES` +for `bgtail`/`bggrep`), but the **write side was unbounded**: a runaway job +(`yes`, a spew loop, a pathological build) fills the disk and can take the +machine down. A secondary effect: `countLogLines` streams the whole file at exit +(bounded memory, unbounded IO). + +## Constraints + +Any fix has to respect these; most of the wrapper's odd shape is one of them. + +1. The cap must live **inside the detached process tree** — pi can exit at any + time, so no parent-side streaming. A watchdog that dies with pi does not keep + the promise. +2. The `__BGRUN_EXIT__` marker must remain the **last non-empty line**. + Completion evidence is the *last* non-blank line only, so a marker that ends + up mid-file is job output that happens to contain the string. A head cap + guarantees this cheaply: the whole capped log is `cap + overhead`, well inside + the 256 KB tail window that finds it. +3. One writer, one offset — two writers into the same file corrupt it. This + includes the exit-code channel, which is why the exit code does **not** travel + through the pipe (a pipeline's `$?` is the reader's). +4. Cap only the redirected stdout/stderr, **never the command's own files**. +5. `maxLogBytes: 0` means unlimited, and takes the legacy wrapper path verbatim — + no fifo, no copier, no notices. + +## The shipped shape + +A fifo plus one copier process, all inside the detached tree: + +```sh +# argv: $1 command, $2 ecfile, $3 fifo, $4 pidfile, $5 truncation-flag file +{ sh -c "$1" 2>&1; ec=$?; ; } >"$3" & # producer; ec out-of-band +{ ; \ + } <"$3" & # cap + flag + drain +wait "$prod"; +rm -f "$2" "$3" "$4" "$5" +printf '\n__BGRUN_EXIT__%d%s\n' "$ec" "$flag" # marker last, flag attached +exit "$ec" +``` + +Points that are load-bearing: + +- **The copier caps, flags, and drains in one process.** `perl` first (unbuffered, + so the live tail is not block-lagged), then `dd iflag=fullblock`, then `head`. + Whatever variant runs, it both writes the kept bytes and consumes the rest, so + the producer is never SIGPIPE'd and the job keeps its real exit code. +- **Completion follows the command, not the stream.** The wrapper waits on the + producer's pid, then allows a short bounded grace (5 × 20 ms) for the copier to + reach EOF. A child the command backgrounded and did not wait for can hold the + fifo open indefinitely; the job must still complete — the stray's output simply + stops being logged, which is what a ceiling is for. +- **The exit code travels out-of-band** (`$2`), so the producer group can capture + it before the pipeline shape gets a say. +- **The flag rides the marker**, not the notice text: `__BGRUN_EXIT__=0 + truncated=67108864`, or `nocap=1` when `mkfifo` failed and the job ran uncapped. + Readers classify by that flag; see "Visibility" below. +- **Staging paths are hardened**: they are `rm -f`'d before use, then written + under `set -C` (noclobber) with `umask 077`, so a planted file or symlink in the + jobs dir cannot be written through. The log itself is opened `0600`, `wx`. +- **`mkfifo` failure degrades loudly**: the job runs uncapped, the log says so + (`__BGRUN_NOCAP__`), and the marker carries `nocap=1`. Losing output is worse + than losing the bound, but "uncapped" must not look like "output was small". + +Accepted price: the log keeps the **first** `cap` bytes, not the tail. There is +no portable in-tree *tail* cap — a ring buffer needs a helper binary, and a +circular/rewritten file breaks every existing reader (marker-at-tail, `bgtail`, +`bggrep`). A job that emits more than 64 MiB is almost always a runaway, so the +head is the useful part. Revisit only if tail retention turns out to matter in +practice. + +## Why not the obvious counters + +Measured on macOS 25.6 with BSD `head`, while the mechanism was being chosen: + +| detection idea | result | +| --- | --- | +| bytes left after `head -c CAP` (`cat \| wc -c`) | **silently 0** whenever the overshoot is smaller than `head`'s read buffer: `CAP=100 N=101` → 0, `CAP=1000 N=1500` → 0, `CAP=8192 N=8193` → 0; only `CAP=65536 N=65537` → 1. `head` over-reads into its buffer and discards the excess. | +| `wc -c bytes +__BGRUN_NOCAP__ log ceiling unavailable (mkfifo failed, so this job ran uncapped) +``` + +- The leading `\n` is required: without it the notice glues onto the last kept + byte, corrupting line counts and `bggrep` line numbers. +- Both prefixes are reserved `__BGRUN_*__` lines, filtered from content readers + exactly like the exit marker, and the *notice identity* is decided by the + marker's flag — never by matching text. A command that echoes a notice-shaped + line therefore cannot make its own log look capped, nor have its own output + discounted as wrapper bookkeeping. +- `countLogLines` drops the whole trailing wrapper block (notice + marker) using + the flag, so "N lines" counts command output only, and the wake's last-line pick + never reports the notice as the job's last output. +- Every agent-facing surface is labelled instead: the wake's Stats line gains + `log truncated at `, `bgtail`/`bggrep` append a note and report + `truncatedAtBytes`, and a configured digest scorecard is **skipped** rather than + scored against a log that lost its end (summaries and failure lists live at the + end, so the numbers would be confidently wrong). + +## Reader bounds + +- A capped log is always slightly **larger** than the cap — notices, marker, and + the separator newlines. So the search-window maximum is the ceiling **plus the + wrapper's overhead** (`readWindowMax()`), not the ceiling itself: clamping to + the ceiling made the documented "widen it to the whole capped log" unreachable. +- A byte window is not a sufficient bound on its own: 64 MiB of one-character + lines is ~33 M line strings, measured at >3 GB of RSS — an OOM on exactly the + log class the ceiling exists for. A scan therefore materializes at most its last + `LOG_SCAN_LINES_MAX` (500 000) lines (~40 MB), and says so when that bit: + `only the last 500,000 lines of that window were searched`. A trimmed window is + never allowed to report a plain "none". +- `countLogLines` takes its tail pread offset from `fstatSync(fd).size` and + refuses to count (returns `null`) past the window bound, so bounding the scan + can never misplace the marker read or drop the count for capped jobs. + +## Config + +- `maxLogBytes` (number, bytes) plus `PI_BGRUN_MAX_LOG_BYTES`; default **64 MiB**, + `0` = unlimited. +- Read at spawn time, so an edit affects the next job only. +- Normalized to an integer in `1 … Number.MAX_SAFE_INTEGER` before it is ever + interpolated into the shell: a fractional value previously truncated to `0` + (= unlimited, silently), and a value above `MAX_SAFE_INTEGER` reached `sh` as + `1e+21`, which the copier rejects while still consuming the stream — i.e. the + log came out empty. + +## Defects already paid for + +Each of these was reproduced before it was fixed, and each has a regression test. +They are listed because they explain why the wrapper is not simpler. + +| symptom | what the shape does now | +| --- | --- | +| `head -c` alone SIGPIPE'd the producer (exit `141`) | copier drains past the cap | +| `mkfifo` unavailable ran uncapped *and silently* | `__BGRUN_NOCAP__` notice + `nocap=1` | +| truncation inferable from printable text | flag in the marker; reserved notice lines | +| `sleep 30 & echo done` produced no wake for 30 s | wait on the command's pid + bounded grace | +| a ceiling of `1e21` emptied the log; `0.5` disabled the cap | integer normalization, floor of 1 | +| the widest window could not cover a capped log | window max = ceiling + overhead | +| a 64 MiB window of tiny lines cost >3 GB of RSS | 500k-line scan bound + labelled note | +| the line bound fired on logs that fit (false caveat) | only report a trim when bytes were actually dropped | +| `countLogLines` bounded its scan by the cap (dropped the count for capped jobs) | bound by the window max; `fstatSync` for the tail offset | +| stale staging files were never swept; sweeping by mtime deleted a *running* job's fifo | sweep by mtime, skipping stems whose `.pid` is a live process | + +## Rejected alternatives + +- **`head -c` without a drain**: producer dies on SIGPIPE (`141`) — hostile to + legitimately verbose builds. +- **pi-side watchdog** (stat running logs, kill and truncate the tail): a soft + bound only while pi lives; the overshoot is write-rate × poll interval, and it + is unbounded if pi died. Keeps the tail, loses the promise. +- **`ulimit -f`**: caps *every* file the job writes (artifacts, downloads) and + kills it (`SIGXFSZ`/`153`). Opt-in material, not a default. +- **Document-and-trim-finished-logs**: no bound at all while the job runs. +- **`dd bs=1 count=CAP` as the front stage**: exact, but one read syscall per + byte (64 MiB = 64 M syscalls) — unusable. +- **`process.execPath` as the reader**: exact count with no coreutils/BSD + variance, but it adds a runtime dependency to the spawn path and still needs + the detached-tree plumbing; the fifo uses only POSIX `sh` + `mkfifo` + a + coreutils/`dd`/`head` copier. + +## Tests + +The suite pins the contract, not the plumbing: exactness at the boundary +(`cap + 1` is capped, exactly `cap` is not), exit-code preservation under +megabytes of overshoot, no staging files left behind, stale staging reclaimed +while a running job's staging survives, the notice unfakeable by job output, +`nocap` visibility, config normalization (`0`, fractional, over-MAX_SAFE), +reader labelling and `truncatedAtBytes`, and the window and line bounds with +their caveats. + +Run with `bun test extension/index.test.ts` (what CI runs) and, by hand, +`node --test extension/index.test.ts` — the second brings the V8/worker_threads +side of `bggrep`'s bounded matching, which Bun does not exercise. diff --git a/skill/run-bg/SKILL.md b/skill/run-bg/SKILL.md index f4fbfba..0908ae2 100644 --- a/skill/run-bg/SKILL.md +++ b/skill/run-bg/SKILL.md @@ -139,8 +139,9 @@ that expensive rather than merely rude. Aggregate, then cap what you print: - One job = one id. Multiple concurrent jobs are fine — each has its own log. - Job logs are capped by default (`maxLogBytes` / `PI_BGRUN_MAX_LOG_BYTES`, 64 MiB; `0` = unlimited) and the cap keeps the **first** bytes. A log that - ends with `[pi-bgrun] output truncated at bytes (first bytes kept)` - hit that ceiling: output past it was dropped, not lost to a failure — the job + ends with `__BGRUN_TRUNC__ output truncated: kept the first bytes` (or + `__BGRUN_NOCAP__ log ceiling unavailable`, when the ceiling could not be + installed and the job ran uncapped) hit that ceiling: output past it was dropped, not lost to a failure — the job still ran to completion with its real exit code, and readers (`bgtail`, `bggrep`, the wake's line count/last line) filter the notice out. The wake's Stats line, `bgtail` and `bggrep` all say when a log was capped (and report @@ -149,8 +150,9 @@ that expensive rather than merely rude. Aggregate, then cap what you print: read a missing digest as "unknown", **not** as "no failures", and do not re-run the command to see the missing tail; raise the ceiling if you need the whole log. The flag lives in the exit marker (`__BGRUN_EXIT__=0 - truncated=`), so treat a notice-looking line printed by the command itself - as content, not as a cap signal. A search window is also limited to its last + truncated=`, or `nocap=1`), never in printable text — the `__BGRUN_*__` + lines are reserved, so a notice-looking line printed by the command itself is + content, not a signal. A search window is also limited to its last 500 000 lines: when that bites, `bgtail`/`bggrep` say so — a "none" from a trimmed window means the head was not searched. - Logs default to `/.pi-bgrun/jobs` in a repo — project-scoped is the From f11906d796ab0b24efc942da69d08245242d8547 Mon Sep 17 00:00:00 2001 From: Lloyd Engebretsen Date: Sun, 20 Sep 2026 19:47:06 -0400 Subject: [PATCH 13/13] docs: gitignore the local bgrun config, and document the dogfood setup MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `.pi/pi-bgrun.json` is per-contributor state, not repo policy: it is read only for a trusted project, it changes what every bgrun job in the checkout does (`showCompletedJobs`, plus a digest that shells out at wake time), and two of the three keys it usually carries are noise (`jobsDir` restates the default). So the repo now ignores its own copy and the maintainer setup lives in docs/dogfooding.md — the config to copy, what each key does, how to see the scorecard on a real run, and how config layering unwinds it. The doc is the live file's own content, so it stays honest by being exercised: both of this maintainer's worktrees run it. README's configuration section says plainly why such a file is not shared. --- .gitignore | 5 ++++ README.md | 6 ++++ docs/dogfooding.md | 75 ++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 86 insertions(+) create mode 100644 docs/dogfooding.md diff --git a/.gitignore b/.gitignore index 845dad5..0164ab6 100644 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,8 @@ dist/ # Transient agent working files — never committed. .pi/wip/ + +# Local pi-bgrun project config (jobsDir / showCompletedJobs / digest) — per +# contributor, not repo policy: it changes what every bgrun job in this checkout +# does, and a digest command is shell run at wake time. See docs/dogfooding.md. +.pi/pi-bgrun.json diff --git a/README.md b/README.md index f84087f..d24c1b9 100644 --- a/README.md +++ b/README.md @@ -208,6 +208,12 @@ config file (trusted projects only) ← environment variables**. - User: `~/.pi/agent/pi-bgrun.json` - Project: `/.pi/pi-bgrun.json` +The project file is per-contributor state, not shared policy: it is read only for +a trusted project, it changes what every `bgrun` job in that checkout does, and a +digest entry runs a shell command at wake time. This repo therefore gitignores +its own; [`docs/dogfooding.md`](docs/dogfooding.md) has the setup its maintainers +run locally (completed jobs visible, a scorecard on `bun test` runs). + ```json { "adoptForeignJobs": false, diff --git a/docs/dogfooding.md b/docs/dogfooding.md new file mode 100644 index 0000000..d8e4a32 --- /dev/null +++ b/docs/dogfooding.md @@ -0,0 +1,75 @@ +# Dogfooding bgrun in this repo + +This repo's maintainers run pi-bgrun on its own test suite. The setup is a +*personal* project config, not repo policy: `/.pi/pi-bgrun.json` is read +only for a trusted project, it changes what every `bgrun` job in the checkout +does, and one of its keys runs a shell command at wake time. So it is gitignored +here — copy the example below into your own working copy if you want the same. + +```json +{ + "showCompletedJobs": true, + "digest": [ + { + "type": "test", + "match": { "command": "*bun test*" }, + "label": "bun-test", + "command": "grep -E '[0-9]+ (pass|fail)$' \"$1\" | tail -5" + } + ] +} +``` + +## What it does + +- `showCompletedJobs: true` — finished jobs stay in the widget and in + `bgstatus` instead of disappearing (the extension's default is `false`). +- `digest[0]` — a **scorecard**: at wake time, for a job whose `type` is `test` + *and* whose command matches `*bun test*`, the `command` runs with `$1` set to + the job's log path, and its stdout is appended to the wake as + `digest (bun-test): …`. Here that prints the suite's own pass/fail lines. + +`jobsDir` is intentionally absent — `/.pi-bgrun/jobs` is the default in +a repo, and the extension adds it to `.git/info/exclude` so logs never show up in +`git status`. + +## Try it + +Start the suite as a job and let the wake carry the scorecard: + +``` +bgrun(command: "bun test extension/index.test.ts", type: "test", name: "unit-tests") +``` + +The wake then carries the suite's own numbers instead of a summary the agent +has to re-derive: + +``` +finished (exit 0) … +digest (bun-test): 193 pass + 0 fail +``` + +(the scorecard is the digest command's stdout, exactly as printed — two lines +here, because `bun test` prints one per counter). + +Selection rules that make this work: entries *declaring* a `type` are considered +first and only for jobs that declared that type, and an entry's `match` must pass +as well — so `type: "test"` with a command that isn't a `bun test` run falls +through to the type-less/glob pass (and, with no entry there, gets no scorecard). + +## Overriding and unwinding + +Config layers are `defaults ← user ← project ← env`, so an environment variable +beats the file (`PI_BGRUN_SHOW_COMPLETED=0`, `PI_BGRUN_MAX_LOG_BYTES=0`). To drop +the setup, delete `.pi/pi-bgrun.json`; nothing else depends on it. + +## See also + +- README: [Digest scorecard (opt-in)](../README.md#digest-scorecard-opt-in) — the + full selector reference, presets (`go-test`, `jest`, `pytest`, `junit-xml`), and + the `custom`/`output` forms. +- The `digest-config` skill — samples a project's real logs, drafts a digest + command, and validates it against green *and* red runs before writing the file. +- The per-project nudge: until a project has a digest, bgrun mentions the option + once (a `.bgrun-used-` marker in the jobs dir records that it happened).