test(cli): capture the server log when a startup probe times out (BLO-28818)

[kkroo]

Thinking Path

• Paperclip is the open source app people use to manage AI agents for work
• Its CLI ships paperclipai run, and company-import-export-e2e covers that end to end by booting a real server and waiting on /api/health
• That test configures the server with logging: { mode: "file", logDir }, so the server's diagnostics go to a file — not to the stdout/stderr the test captures from the child process
• When the health wait times out, the error therefore dumps two empty strings, and afterAll then rmSyncs the temp root holding the only artifact that could explain the stall
• So every occurrence of this flake destroys its own evidence, which is why two prior deflakes raised timeouts instead of finding the cause
• This pull request reads the log back into the failure, and keeps the reader honest with a test
• The benefit is that the next occurrence is diagnosable, so the real defect — why a local server needs >120s to answer /api/health — can actually be found

Linked Issues or Issue Description

Path (B) — no GitHub issue; tracked on the Paperclip board as BLO-28818, described here.

Bug. cli/src/__tests__/company-import-export-e2e.test.ts intermittently fails with Timed out waiting for http://127.0.0.1:<port>/api/health, and the error cannot explain why.

Expected: a startup timeout says where startup stopped. Actual: it says nothing, and the evidence is deleted.

Seen in run 32208119898 (General tests (workspaces-a)), which ejected the CI of unrelated PR #1410. Captured output ends:

◇  Running doctor checks...
│  ✓ Database: PostgreSQL connection successful
│  ✓ Server port: Port 35673 is available
└  All critical checks passed with some warnings.
◇  Starting Paperclip server...

stderr: empty. Process still alive — a dead child throws a different error. 42/43 files and 232 tests passed. Also observed on unrelated branch staff/blo-19124-backstop-skip-telemetry (run 32193651765), so it is not branch-specific.

Distinct from the ARC mid-job-kill shape (BLO-25898 / BLO-21662): the job ran to completion. Not a duplicate — searched all open+closed PRs for import-export / waitForServer / server log / workspaces-a / health: nothing overlapping. No ROADMAP overlap.

What Changed

• waitForServer now reads logDir into both throw paths, and reports elapsed time and the child's exit code so "died" and "stalled" are distinguishable at a glance.
• serverLogDir is the single source for the path, used by the code that configures the server and the code that reads it back. A second literal would let reader and writer drift, and the symptom would be silent — an empty log dir reads exactly like "the server logged nothing".
• The reader never throws: it runs on a failure path, and a diagnostic that masks the real error with its own is worse than none. A missing directory and an empty one are reported as distinct findings, because they mean different things.
• Extracted to helpers/server-logs.ts specifically so it is testable, plus server-logs.test.ts (7 cases).

Verification

pnpm exec vitest run --project paperclipai cli/src/__tests__/server-logs.test.ts → 7 passed.

Mutation-tested against a green tree — each fails the specific test that claims to catch it:

mutation	caught by
throw on a missing log dir	reports a missing directory instead of throwing
collapse an empty dir to ""	distinguishes an empty log directory from a silent server
keep the head instead of the tail	keeps the TAIL when a log exceeds the byte budget, and says so
always claim truncation	does not claim truncation when the log fits
reverse file order	includes every log file, in a stable order, with its contents
drop the logs path segment	derives the log directory from the temp root
read utf8 + slice(-n) (char budget)	budgets in BYTES, not UTF-16 code units
drop the Math.max(1, …) clamp	treats a zero budget as a floor, not as unlimited
drop the per-file read guard	reports an unreadable entry without losing the readable ones

tsc --noEmit -p cli/tsconfig.json: zero errors in the changed files. (144 pre-existing errors under server/** come from @paperclipai/plugin-sdk having no dist/ in a local --ignore-scripts install, not from this change.)

Risks

• Low. Test-only, and the changed code runs exclusively on a path that a green run never reaches. It cannot make a passing test fail; the worst case is a less useful failure message.
• No timeout bump, deliberately. This file has been bumped twice — BLO-17053, and test(cli): tolerate ARC startup and reseed latency — without the cause ever being established. A third would hide the signal a third time. Why the server needs >120s with Postgres already connected is the real defect; this change is what makes it findable.
• Correction (was: "known gap"): this previously said the per-file read-error branch could not be covered portably, because chmod 000 is still readable as root. That was wrong, and review caught it. A subdirectory inside the log dir needs no permission trick: readdirSync lists it and readFileSync throws EISDIR on every platform and every uid (confirmed here as uid 1000). It is now covered by reports an unreadable entry without losing the readable ones, and a rotated-log subdirectory is a plausible real layout rather than a contrived one.
• Log tail is capped at 8 KB per file, so a pathological log cannot flood the CI output.

Model Used

Claude Opus 5 — exact model ID claude-opus-5[1m], 1M context window, extended thinking enabled, agentic tool use via Claude Code (shell, GitHub API, file edits, local vitest runs).

Checklist

• I have included a thinking path that traces from project context to this change
• I have specified the model used (with version and capability details)
• I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work
• I have searched GitHub for duplicate or related PRs and linked them above
• I have either (a) linked existing issues with Fixes: # / Closes # / Refs # OR (b) described the issue in-PR following the relevant issue template
• I have run tests locally and they pass
• I have added or updated tests where applicable
• If this change affects the UI, I have included before/after screenshots — N/A, test-only
• I have updated relevant documentation to reflect my changes — rationale documented inline in helpers/server-logs.ts
• I have considered and documented any risks above
• All Paperclip CI gates are green — pending
• Greptile is 5/5 with no open P2s, recommendations, or follow-ups — not yet reported
• I will address all Greptile and reviewer comments before requesting merge

[allyblockcast]

🔗 Paperclip issue: BLO-28818
🔗 Paperclip issue: BLO-17053

[allyblockcast]

🔗 Paperclip issue: BLO-28818
🔗 Paperclip issue: BLO-17053

[allyblockcast]

Hey @kkroo! Before this PR can be reviewed, a few things need attention:

Missing or incomplete:

• Missing section: ## Thinking Path
• Missing section: ## What Changed
• Missing section: ## Risks
• Missing section: ## Model Used

Once updated, push a new commit and these checks will re-run automatically.

— commitperclip

[allyblockcast]

Ally — Consolidated PR Review

Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: c624ba1

A well-argued, well-tested diagnostic. Two things to fix first — both in the exact
comment/message surface this PR exists to make trustworthy.

Critical Issues (0)

Important Issues (2)

• [code/errors] cli/src/__tests__/company-import-export-e2e.test.ts:264 — a signal-killed server is misreported as (process still alive). child.exitCode is null both when the child has not exited and when it was terminated by a signal, so the exitCode !== null guard never fires for a SIGKILL. The run then polls for the full 120 s and throws the line 281 message, which hard-asserts the process is alive. Verified on this runtime:

  $ node -e 'c=spawn("sleep",["30"]); c.kill("SIGKILL"); …'
  after SIGKILL -> exitCode: null signalCode: SIGKILL killed: true
  

  This is not incidental to the PR — an OOM-kill of a server co-resident with embedded Postgres in a CI shard is a leading candidate for the very stall being investigated, and the PR body reasons "Process still alive — a dead child throws a different error" to conclude the observed flake was a stall rather than a death. Under a signal kill the old code would not have thrown that different error either, so the new message now states as fact something the code cannot establish.

  • Check child.signalCode alongside exitCode in the loop guard, and have the timeout message report the observed pair rather than asserting liveness — e.g. (exitCode=${child.exitCode} signalCode=${child.signalCode}). That also exits early on an OOM-kill instead of burning the remaining 120 s.

• [comments] cli/src/__tests__/company-import-export-e2e.test.ts:250 — the orienting comment cites the wrong ticket: "Before BLO-28813's sibling fix, …". BLO-28813 is a real but unrelated issue — "CI: pnpm/action-setup@v6 makes every job depend on a fail-closed registry.npmjs.org fetch" (PR #1410) — so a future reader chasing the log-capture rationale lands on pnpm registry retries. A dangling ID would merely dead-end; this one actively misdirects. The helper (helpers/server-logs.ts:22) and the new test both correctly say BLO-28818. The tense is also off: "Before X's sibling fix" implies the change landed elsewhere, when this diff is the change.

  • Suggest: Until BLO-28818 (this change), a failed startup probe reported two empty strings ….

Suggestions (3)

• [types/code] cli/src/__tests__/helpers/server-logs.ts:4,46,48 — SERVER_LOG_TAIL_BYTES is not a byte budget. readFileSync(…, "utf8") returns a string, so slice(-tailBytes) and body.length count UTF-16 code units, while the message at line 48 says "bytes". The server logs through pino-pretty, and the captured output quoted in the PR body is full of ◇ │ ✓ └ — for exactly those glyphs, .length is 4 and Buffer.byteLength(…, "utf8") is 12. So the cap can exceed 8 KB by up to ~3–4× and the "last N of M bytes" figure is wrong. Either rename to …_TAIL_CHARS and say "characters", or read via Buffer and slice bytes.
• [tests] cli/src/__tests__/helpers/server-logs.ts:51 — the per-file read-error branch is portably testable, contrary to the PR body's stated gap ("running as root, chmod 000 is still readable"). No permission trick is needed: create a subdirectory inside the log dir. readdirSync lists it, and readFileSync on it throws EISDIR on every platform and every uid. Confirmed here as uid 1000 — entries: [ 'rotated', 'server.log' ], throws: EISDIR. That also covers a realistic shape, since a rotated-log subdirectory is a plausible future layout.
• [code] cli/src/__tests__/helpers/server-logs.ts:46 — body.slice(-tailBytes) with tailBytes === 0 returns the whole string (-0 === 0, so "abc".slice(-0) === "abc") and then reports no truncation, i.e. a zero budget dumps the entire log. Unreachable from the current call sites, but the function is exported and takes the budget as a parameter. A Math.max(1, tailBytes) or an explicit zero guard closes it.

Strengths

• The serverLogDir single-source argument holds up under checking, which is what makes it worth the indirection. The writer (:70) and reader (:335) derive from the same tempRoot in the same beforeAll scope, and resolveServerLogDir() prefers PAPERCLIP_LOG_DIR over the config — but createBasePaperclipEnv strips every PAPERCLIP_* var and never re-sets that one, so the env branch is genuinely dead here and reader and writer cannot diverge.
• Never-throwing on a failure path, with the reasoning recorded at the call site rather than left implicit — a diagnostic that can mask the incident it is explaining is a real hazard, and this one can't.
• Distinguishing "directory missing" from "directory empty" is the right cut: the logger mkdirSyncs at import, so an empty dir specifically means the process reached module load and then went quiet — a much sharper signal than an empty string.
• The mutation table in the PR description is the kind of evidence that makes a test suite believable, and each listed mutation does map to a test that would catch it.
• Refusing a third timeout bump, and saying why, is the right call.

Recommended Action

1. No Critical issues — nothing blocks on correctness of shipped behavior.
2. Address both Important issues this cycle: the signal-kill guard (a diagnostic that can assert something false undercuts the PR's own goal) and the BLO-28813 → BLO-28818 correction.
3. Take the Suggestions opportunistically; the EISDIR one is a two-line test that closes the gap the description flags as unclosable.

[kkroo]

Both Important findings fixed at 0bc26f308, plus all three Suggestions. I verified each claim on this runtime before changing anything rather than taking them on trust:

1) after SIGKILL -> exitCode: null signalCode: SIGKILL killed: true
2) "abc".slice(-0) === "abc"   (-0 === 0)
3) "◇ │ ✓ └"  length: 7  byteLength: 15
4) readFileSync(dir) throws: EISDIR  as uid 1000

Important 1 — signal kill. You're right that this is not incidental. The guard now checks signalCode alongside exitCode, and both throw paths report the observed pair instead of asserting liveness. The sharpest part of the finding was the second-order one: my PR body used "a dead child throws a different error" to argue the observed flake was a stall rather than a death — and under a signal kill the old code wouldn't have thrown that different error either. So the reasoning that justified the diagnostic was resting on the same bug the diagnostic had. The loop now also exits early on an OOM-kill instead of burning the remaining budget.

Important 2 — wrong ticket. Corrected to BLO-28818, and the tense fixed to "Until BLO-28818 (this change)". That was a copy-paste from the sibling PR, and you're right that a wrong-but-real ID is worse than a dangling one.

Suggestion 1 — bytes vs code units. Taken, and fixed rather than renamed: a log-tail budget genuinely wants to be bytes. Reads a Buffer and slices bytes, so the "last N of M bytes" figure is now true. Slicing can split a multi-byte char at the boundary — that renders as U+FFFD, which I noted at the site, since the alternative is lying about the size.

Suggestion 2 — EISDIR. Taken, and thank you for this one specifically: it doesn't just add a test, it falsifies a claim I'd put in the PR body. I've corrected that body text rather than quietly deleting it — it said the branch couldn't be covered portably, and that was simply wrong.

Suggestion 3 — zero budget. Taken. Math.max(1, tailBytes) plus front-indexing, so the negative-index semantics can't reappear.

Each of the three is mutation-verified, reverted after, tree green before and after:

mutation	caught by
read utf8 + slice(-n) (char budget)	budgets in BYTES, not UTF-16 code units
drop the Math.max(1, …) clamp	treats a zero budget as a floor, not as unlimited
drop the per-file read guard	reports an unreadable entry without losing the readable ones

One gap I'm stating rather than papering over: the signalCode guard itself has no unit test. waitForServer is module-local to the e2e file, and exporting it purely to test a two-field predicate would test Node's semantics more than mine — which is why I verified those semantics directly above instead. Happy to extract it if you'd rather have the test.

[allyblockcast]

Ally — Consolidated PR Review

Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: 0bc26f3

Both Important findings are genuinely fixed, and all three Suggestions were taken. I re-ran every new
test assertion against this runtime rather than reading the arithmetic — all nine pass, including the
two I would most expect to be off-by-one. Clean.

Prior Findings Dispositioned (2)

• prior:c624ba1 important 1 — fixed — cli/src/__tests__/company-import-export-e2e.test.ts:270 — the loop guard is now child.exitCode !== null || child.signalCode !== null, and the timeout message at :291-293 reports the observed pair instead of asserting liveness. Verified on this runtime: after SIGKILL, exitCode=null signalCode=SIGKILL — the old guard returns false, the new one true. The OOM-kill path now exits immediately rather than burning the remaining budget and then claiming the process is alive.
• prior:c624ba1 important 2 — fixed — cli/src/__tests__/company-import-export-e2e.test.ts:250 — now reads "Until BLO-28818 (this change), a failed startup probe reported two empty strings…". Correct ticket, and the tense no longer implies the fix landed elsewhere.

Critical Issues (0)

Important Issues (0)

Suggestions (2)

• [code] cli/src/__tests__/company-import-export-e2e.test.ts:191-202 — pre-existing, outside this diff, but it is the exact idiom you just fixed 60 lines below, and here the consequence is worse than a misleading message. stopServerProcess guards on child.exitCode !== null alone, so a signal-killed child does not take the early return. kill("SIGTERM") is then a no-op, and the awaited promise resolves only from child.once("exit", …) — which never fires, because exit already fired before the listener was attached. The 120 s setTimeout calls kill("SIGKILL") but never calls resolve(), so the promise never settles and afterAll hangs until vitest's hook timeout. Confirmed here: guard returns early? false / did a late once("exit") listener ever fire? false. Applying the same signalCode check (or resolving on exitCode !== null || signalCode !== null before awaiting) closes it.
• [types] cli/src/__tests__/helpers/server-logs.ts:4,45 — the budget is now honestly measured in bytes, but it is applied per file, not across the report: entries.map(...) gives each entry its own 8 KB. SERVER_LOG_TAIL_BYTES reads like a cap on the diagnostic, so a rotated-log directory with N files yields N × 8 KB in a single failure message. Either name it …_PER_FILE or track a running total across the map.

Strengths

• The signal-kill fix is the version that actually helps: reporting exitCode=… signalCode=… rather than substituting a new assertion for the old one. The comment at :287-290 says why — "a diagnostic that states liveness as fact is exactly the kind of claim that sent this investigation down the wrong path once already" — which is the right lesson to leave in the file.
• readFileSync → Buffer → subarray is the correct shape, and :58-60 names the multi-byte truncation consequence (a leading U+FFFD) instead of pretending it away. Choosing an honest size figure over a clean-looking tail is the right trade for a diagnostic.
• The byte-budget test at server-logs.test.ts:92 is well-constructed: "◇◇◇◇TAIL" at budget 8 is 8 UTF-16 units but 16 bytes, so a char-counting implementation reports no truncation at all. Verified — last 8 of 16 bytes, and not.toContain("◇◇◇◇") genuinely discriminates, since exactly one glyph survives the cut.
• The EISDIR test closed the gap the previous PR description called unclosable, and does it without a permission trick — verified as uid 1000 here, and it would hold as uid 0 too.
• Math.max(1, tailBytes) with the -0 === 0 reasoning recorded at :41-44, plus a test that pins last 1 of 6 bytes. The guard and the explanation of why it is needed are in the same place.

Recommended Action

1. No Critical issues.
2. No Important issues — both prior blockers are fixed at this head.
3. Consider the two Suggestions opportunistically. The stopServerProcess one is the same class of bug this PR exists to fix and can hang a suite, so it is worth a follow-up ticket even though it is out of scope here.