Skip to content

Commit ec9160f

Browse files
Brooooooklynclaude
andauthored
fix(api): stop losing the tail of every container build log (#252)
* fix(api): preserve container build log tails * fix(api): serialize terminal log pulls with teardown * fix(api): reconcile concurrent terminal teardown * fix(api): neutralize unknown teardown outcomes * fix(api): finalize recovered terminal checks * test(api): cover recovered check finalization * fix(api): align recovered teardown markers * fix(api): retry the terminal log drain inside the agent barrier onError is the one terminalizer that does not force-stop, so its single best-effort pull was also the last one: a transiently unavailable agent port swallowed the failure and the check run was finalized with no diagnostic tail, even though the agent was still holding its control server open waiting for our cursor acknowledgement. The scheduled pollLogs backstop does not save it either - it either joins the same failed single-flight request or makes one terminal, non-rearming attempt of its own. Retry on that live-terminal path within the agent's idle window (LOG_TERMINAL_DRAIN_RETRY_WINDOW_MS = 7000, one POLL_SECONDS of margin inside the 8s barrier). runLogPull now reports whether it reached a successful terminal/acknowledgement page, and pullLogsOnce accepts a caller budget so a retry cannot open a fresh whole-drain budget just before the outer deadline. teardownInFlight is rechecked after every awaited pull - including a successful one - so finalization cannot outrun a teardown that began during the I/O. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011fMATP1nmroN12aKoX2EzJ * fix(api): bound log ingestion with a deterministic work budget LOG_DRAIN_BUDGET_MS cannot bound a pull callback's CPU. A deployed Worker's clock advances on I/O, not during CPU work, so it measures the agent's response latency and scores every JSON parse, SQLite insert and WebSocket fan-out between the fetches as free. MAX_LOG_PULL_PAGES bounds the response SIZE a callback may take, and bounding the size of the data does not bound the work done on it: 32 maximum pages is 64 MiB copied once per subscriber plus one, and all of it sits in front of the SIGTERM a cancel or timeout depends on, against the invocation's CPU allowance. Charge each ingested row (1 + subscribers) * max(1, ceil(len / LOG_SINK_OP_PAYLOAD_BYTES)) sink operations and stop the callback once MAX_LOG_SINK_OPS_PER_DRAIN is spent. The cap is MAX_STORED_LOG_LINES because that is the DO's retained window - rows ingested past it in the same callback are deleted by that same batch's eviction, so a larger budget could only buy work whose result is immediately discarded. Checked between pages, never inside one: a page is ingested atomically, so the cursor never advances past rows that did not reach the sink and one maximum page may overshoot. A callback stopped by the budget skips its final acknowledgement request; the next one's since=<advanced cursor> is that acknowledgement, and onError's retry loop supplies it on the terminal path that has no next callback. Regressions freeze Date.now() for the whole drain, so the wall-clock deadline can never expire and only the work bound can stop the loop. Each covers a dimension the others do not: page rows, WebSocket fan-out width, row payload bytes, and the teardown path reaching its SIGTERM. All four take 32 pages without the budget. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011fMATP1nmroN12aKoX2EzJ * docs(meta): record the clock-cannot-bound-work lesson Pairs with the existing "a page cap bounds WORK, not LATENCY" entry. The whole-drain deadline added for that one turned out to bound nothing on the work axis: a Worker's clock advances on I/O and stands still during CPU. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011fMATP1nmroN12aKoX2EzJ --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent b4c1774 commit ec9160f

9 files changed

Lines changed: 4370 additions & 275 deletions

File tree

‎README.md‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -324,7 +324,11 @@ Staging hostnames are gated by Cloudflare Access (GitHub organization `voidzero-
324324
- **WfP deploys mirror assets to KV/R2 as a safety net** — Projects with type `"void"` or `"framework"` still serve assets via CF's per-worker `ASSETS` binding. Each deploy _also_ mirrors assets to `STATIC_ASSETS`/`STATIC_ASSETS_R2` and writes a serving manifest to `ROUTING` KV. When CF returns the `Assets have not yet been deployed to this script.` stub (see `meta/design-docs/0065`, `meta/design-docs/0066`), dispatch detects it and serves from the mirror. CF remains primary; the mirror is only consulted on stub detection.
325325
- **Deploy-on-GitHub builds run the real `void deploy` CLI** — The build environment (CF Container or GitHub Actions) does not re-implement packaging or POST artifacts to the API. It runs `npx void deploy` with a short-lived, project-scoped deploy token (`aud: "deploy"`, 15-min TTL, minted by `src/auth/deploy-token.ts`). There is **no** `POST /builds/:id/artifacts` endpoint and `routes/deploy.ts` is unchanged. Design docs `0010`/`0011` predate the JSON-manifest, direct-to-R2 deploy endpoint and describe a stale artifact-upload premise — do not follow them verbatim.
326326
- **Container→DO live-log transport (now wired via a DO pull-loop)** — `BuildManager` PULLS build-log lines from the build container's agent: a `pollLogs()` loop uses a non-starting `getTcpPort().fetch()` (deliberately **not** `containerFetch`, which would auto-resurrect an exited container) against the agent's `GET /logs?since=N`, advancing an in-memory cursor (~1s cadence, self-terminating on terminal status) and feeding the existing SQLite `logs` table + WebSocket fan-out. (This replaced the earlier "not yet wired" follow-up; the chosen mechanism is the DO pull-loop, **not** a `ContainerProxy` `outboundByHost` outbound interceptor.) The DO also exposes a read-only `GET /logs?since=N` returning `{ lines, lastSeq }`. The internal admin panel surfaces this: a per-project Builds section on `/admin/projects/:id` (ongoing build highlighted) and a build page `GET /admin/builds/:id` with a client-side polling live-log panel (NOT a WebSocket) for container builds. `github_actions` builds have no DO log store and instead link out to their GitHub Actions run. Users can now also view container build logs for their own projects via the CLI (`void build logs`), which fronts the same DO log store through the owner-guarded projects-router routes `GET /projects/:id/builds` and `GET /projects/:id/builds/:buildId/logs` (`github_actions` builds return their Actions run URL instead). Container-build check runs now also embed the last 100 captured log lines in the check-run `output.text` at completion (all terminal outcomes; `github_actions` checks unchanged — they link to the Actions run).
327+
- **The pull-loop needs both an exit acknowledgement barrier and a teardown drain** — The DO pull-loop is the only path that durably ingests container logs, so the agent keeps its control server alive after the build process exits until the DO has acknowledged every recorded sequence. The wait is progress-aware: an 8s idle deadline resets only when the acknowledged cursor advances, while a 120s absolute cap prevents a peer that supplies endless partial progress from pinning the container; `enforceTimeout` is armed with 125s of post-build grace. Teardown cannot rely on that natural-exit path because SIGTERM ends in `process.exit(1)`, so `forceStopContainer()` owns one whole first-caller-wins single-flight sequence: join any scheduled pull, take one fresh paginated snapshot when the first caller requested a drain, re-read liveness, then attempt stop/destroy. Later teardown callers join that same sequence and cannot start a late pull after signalling or override the first caller's drain policy. A manager termination marker is appended only after at least one control call against a freshly-live container succeeds; a natural exit during the drain emits no false marker. Pull callbacks retain a 4s whole-drain deadline plus per-request timeouts, and paging/ring limits are measured in serialized bytes so an oversized backlog advances rather than livelocking. Keep pulls on `getTcpPort().fetch()` rather than `containerFetch`, which can resurrect an exited container.
327328
- **Build children must be told `CI=true`, and the check-run tail is terminal-rendered** — The container agent hands every build child `CI: 'true'` (`nonInteractiveEnv()` in `container/build-agent.mjs`, merged into both install and `void deploy` spawns). This is load-bearing: the Void CLI's `createSpinner()` takes its plain logging path only when `@clack/prompts` sees that exact value; otherwise spinner frames are emitted as `ESC[1G ESC[J` with no newline and hundreds of erased frames arrive as one captured line. Independently, `formatLogTailMarkdown` renders each line before byte accounting because arbitrary third-party build tools may still emit terminal controls, and a Markdown code fence prints rather than interprets them. Render-time only: the live tail and `void build logs` retain color.
328329
- **Use a maintained terminal emulator for check-run text, with deterministic outer bounds** — `sanitizeLogLineForMarkdown` uses `@xterm/headless`, the same VT engine used as the differential oracle, rather than owning another partial CSI/ESC screen model. Tokenizers such as ANSI strippers are insufficient because correctness depends on state: cursor movement, configured tab stops, protected cells and selective erase, wide glyphs, REP, C0/C1 transitions, string controls, and alternate-buffer/history resets all affect what remains visible. The agent preserves each captured row's exact CR/LF/CRLF/EOF ending internally, and the newest 100-row check-run window is rendered chronologically through one persistent xterm so parser state and terminal modes survive row boundaries; that bounded window is the explicit terminal-state reset boundary. The internal ending field is additive and is not exposed by the public log APIs; existing DO tables are upgraded in place with unknown provenance left nullable, letting the formatter retain legacy CRLF-between-rows behavior without fabricating a delimiter after the final row. Plain rows bypass the emulator. Controlled rows use one fixed 32K-column grid, are preflighted for input size plus work-amplifying commands, and reject insert mode; ordinary SGR and cursor parameters are not treated as parser work. The newest tail rows also share a deterministic input/work budget. If a state-mutating group inside the window must be omitted, the formatter fails closed rather than restarting with invented terminal state. Do not replace these limits with `performance.now()` deadlines: deployed Workers do not advance their clocks during CPU work, and xterm has handlers that loop or allocate directly from `Ps` before a caller can inspect time. Correctness remains pinned by fixed and deterministic-fuzz comparisons in `test/unit/sanitize-log-line-oracle.test.ts`.
330+
- **Drain-barrier timing is progress-aware** — A pull callback may spend `LOG_DRAIN_BUDGET_MS = 4000` draining paginated responses and re-arm one second later, so a deep 16MiB ring can require several productive callbacks. The agent now keeps an 8s idle deadline that resets only when the acknowledged cursor advances, plus a non-resettable 120s absolute cap; a dead DO still releases its container after 8s, while a slow healthy drain can finish the conservative 32-request envelope. The DO grants 125s of post-build grace so it cannot overwrite an already-live deployment while that barrier is active. Tests pin the idle, absolute, grace, and deploy-token relations. `onError` is the one terminalizer that does not force-stop, so it owns its own bounded retry loop (`LOG_TERMINAL_DRAIN_RETRY_WINDOW_MS = 7000`, one `POLL_SECONDS` of margin inside the agent's 8s idle barrier): a transient port failure or a budget-exhausted pull is retried instead of being treated as the final attempt, and a teardown that starts during any of those pulls is joined before the check run is finalized.
331+
- **Log ingestion is bounded by deterministic WORK, not only by a clock** — `LOG_DRAIN_BUDGET_MS` cannot bound a pull callback's CPU: a deployed Worker's clock advances on I/O, not during CPU work, so it measures the agent's response latency and scores every JSON parse, SQLite insert and WebSocket fan-out between the fetches as free. `MAX_LOG_PULL_PAGES` bounds the response SIZE (32 x `MAX_LOG_RESPONSE_BYTES`), and bounding the size of data does not bound the work done on it — 64 MiB of rows is `(1 + subscribers)` copies of itself, all of it in front of the SIGTERM a cancel or timeout depends on. `MAX_LOG_SINK_OPS_PER_DRAIN` (= `MAX_STORED_LOG_LINES`, the DO's retained window — a bigger budget could only buy work the same batch's eviction discards) charges each ingested row `(1 + subscribers) * max(1, ceil(len / LOG_SINK_OP_PAYLOAD_BYTES))` and stops the callback when it is spent. Checked BETWEEN pages only: a page is ingested atomically, so the cursor never advances past rows that did not reach the sink and one maximum page may overshoot. A callback that stops on the budget skips its final acknowledgement request; the next one's `since=<advanced cursor>` is that acknowledgement.
332+
- **Drain authorization and reconciliation follow-up (current rule)** — A DO-local terminal status does not prove the Postgres build row is terminal: one teardown writes local state before awaiting its revocation CAS, so a concurrent `cancelBuild` can observe terminal locally while the deploy token is still authorized. That path must perform a bounded authoritative row read and drain only when the row is terminal or absent; an active, failed, or timed-out read skips straight to the signals. A bounded reconciliation read is also the only row read that path may depend on: pass both its `status` and `check_run_id` into check-run finalization. An explicit null id means the authoritative row had none and suppresses a second, unbounded fallback read while still allowing an in-memory or DO-storage id.
329333
- **`PINNED_VOID_CLI_VERSION` must equal the framework submodule** — The build container's fallback CLI version (`build-manager.ts`) applies only to repos with **no local `void` dependency**, so drift is invisible in every normal build; it silently sat at `0.9.1` while the submodule moved to `0.10.x`. `build-manager.test.ts` now asserts it against `framework/packages/void/package.json`. Bump the constant whenever the submodule pointer moves.
330334
- **`github_actions` "Void Build" check run is create-at-OIDC / complete-from-webhook** — The Actions executor has no BuildManager DO, so the "Void Build" GitHub Check Run is created (`in_progress`) once at the OIDC exchange (`routes/auth-oidc.ts`) and guarded on `!build.check_run_id` so a repeated exchange that REUSES the in-flight build never POSTs a second run / overwrites the id. It is completed from `workflow_run:completed` (`routes/webhooks.ts`) with a conclusion mapped from GitHub's `workflow_run.conclusion` (success→success, cancelled→cancelled, timed_out→timed_out, else failure), driven INDEPENDENT of our internal build-status CAS — so a build terminalized out-of-band (push-supersede, OIDC latest-wins, disconnect, app/repo removal, teardown, reaper) still gets its check completed. Both calls are best-effort. The OIDC create+persist is awaited SYNCHRONOUSLY (before the deploy token is returned) so `check_run_id` is durable before the deploy runs — this is what makes the `!build.check_run_id` guard race-free for sequential retries and closes the completion-miss window; `setBuildCheckRunId` is CAS `check_run_id IS NULL` (immutable once set). The webhook completion is deferred via `executionCtx.waitUntil` (off the 2xx and off the critical token-revoking DB path; idempotent, and a redelivery re-completes). Residual bounded orphans (check may stay `in_progress`): app/repo/connection removed mid-run (GitHub unreachable for the PATCH), a genuinely missed completion webhook (past the reaper timeout), or a pathological pair of TRULY CONCURRENT OIDC exchanges for the same run+attempt (duplicate check, one orphaned) — all accepted, mirroring the container path's best-effort boundary.

0 commit comments

Comments
 (0)