Skip to content

Report compile progress live and fail loudly on a stalled agent (#4) - #22

Merged
slalph merged 7 commits into
mainfrom
fix/4-compile-progress
Aug 1, 2026
Merged

Report compile progress live and fail loudly on a stalled agent (#4)#22
slalph merged 7 commits into
mainfrom
fix/4-compile-progress

Conversation

@slalph

@slalph slalph commented Aug 1, 2026

Copy link
Copy Markdown
Contributor

Closes #4.

What the issue asked for, and what I found

The issue reports a compile printing one line and then going silent for over two hours. Investigating the runtime, the silence and the hang turned out to be two separate defects, and one of them was hiding output slc already had:

The progress already existed and was thrown away. A compiled phase's runtime emits the same human status lines playbook run prints as state transitions happen. The SLC port adapter buffered them into a diagnostics array that the bin only printed after the whole run returned — by which time they are useless. The step loop also knew every phase, target, and timing and reported none of it.

Nothing bounded an agent call in time. Cligent exposes maxTurns and maxBudgetUsd but nothing time-based; the transport awaited the next adapter event indefinitely and the bin set no deadline. A network-stalled session parked the pipeline forever, with Ctrl-C the only recourse — exactly the 123-minute stall measured in the issue.

I also dug into why a five-line workflow is slow at all. Each compiled phase costs three strictly serialized cold agent sessions — a judge classification of the seeded Boss turn, the transformation Captain session, and a judge adjudication of its reply — all with resume: false, and the Captain prompt is a fixed ~9.3K-token, 155-constraint prompt baked in at link time regardless of how small the input is. That cost is owned by the pinned artifacts and @sublang/playbook, not by this repo's generic mechanics, so this PR does not try to reduce it — it makes the spend visible and bounds the failure mode, so waiting is informed rather than blind. Reducing it needs artifact/engine changes under a later decision.

What this PR does

Recorded as DR-019 / IR-019, with new items CLI-32–37 and PHEXEC-36–38 and a PHEXEC-25 amendment for streaming.

  • Per-phase progress on stderr — start, finish, and failure lines with elapsed times, emitted by executeSteps through a new optional progress sink on SlcDeps.
  • Live status streaming — a compiled phase's emitStatus/telemetry now reaches the sink as it happens instead of being drained at the end; playbook.trace payloads stay excluded, and streamed lines are not duplicated into diagnostics. Hosts that supply no sink keep the previous behavior, so the library API is unchanged for embedders.
  • A 30-second silence-bounded heartbeat, so the terminal is never quiet longer than the bound while work is in flight.
  • An inactivity watchdog — an agent call observing no adapter event for stallTimeout seconds (new config key, SLC_STALL_TIMEOUT override, default 600, 0 disables) is aborted and reported as a failed phase naming the inactivity duration. Activity is any adapter event, since the reliable event subset differs per adapter. No retry, and a pinned phase still fails closed.
  • Measured time estimates — README and both demo READMEs now state measured ranges (tens of minutes to >2h for a compile of the five-line workflow; ~51 min for the precompiled demo run) and say plainly that duration is agent- and workload-dependent.

I deliberately chose an inactivity watchdog over a per-phase deadline: phase durations legitimately range from minutes to hours, but event silence does not. The 600-second default is generous on purpose — one long tool execution or model turn is legitimately event-silent on every adapter — so the goal is turning an indefinite hang into a loud, attributed failure, not policing phase length.

Defects found while verifying, and fixed here

Driving the built CLI (not just the unit tests) caught a bug in my own first cut: I had unref()'d the watchdog timer, so Node exited with an unsettled-await warning before the timeout could fire whenever the stalled transport held no I/O of its own. The unit test had passed because vitest holds the event loop open. The timer is now referenced, and the regression test asserts the production timers' ref state directly, since an injected fake bypasses the property under test.

An adversarial review pass then confirmed two more, both fixed in dc4265f:

  • A phase that completed inside Cligent's 500 ms post-abort drain was reported as a stall, discarding a finished, expensive phase and returning a resume token for a session that had actually succeeded. The observed outcome now wins over the stall verdict; a genuine hang drains to interrupted, so real stalls are unaffected.
  • A stall timeout above Node's timer range was accepted and then silently clamped to 1 ms, aborting every agent call immediately — the exact inversion of the setting's purpose, reachable by writing milliseconds where seconds were meant. Both configuration sources now refuse an out-of-range window.

The same review confirmed three test gaps by mutation, all closed: progress liveness was untested (buffering everything until the run settled passed every assertion — and liveness is the entire point of the issue), the bin's compiled-status wiring was untested end to end, and the silence-window reset assertion could not fail.

Verification

  • npm run release:check passes in full (format, lint, build, 669 tests, definitions, release workflow, artifacts, pins, en+zh demo, package smoke).
  • Each of the five behavioral fixes is mutation-checked: reverting any one of them turns the suite red.
  • Driven end-to-end against the built CLI: progress lines render live with stdout reserved for artifact paths; the heartbeat fires at 30s and 60s during a 70-second phase; a transport that emits one event and then waits forever fails at the configured timeout with a report naming the phase, target, and cause.

Not merging — this is for your review.

slalph and others added 7 commits August 1, 2026 04:10
Record the decision resolving issue #4: per-phase progress lines with
elapsed times on stderr, live streaming of compiled-runtime status, a
30 s silence-bounded heartbeat, and a configurable agent-inactivity
watchdog that fails a stalled call loudly instead of hanging forever.
Amend PHEXEC-25 for streaming, add CLI-32..37 and PHEXEC-36..38, and
index DR-019/IR-019 in the map.

Co-authored-by: Claude Fable 5 (coder) <cligent@sublang.ai>
Resolve the issue-#4 silence: the step loop now emits phase
start/finish/failure events with elapsed times through a progress sink
on SlcDeps, the bin renders them on stderr with a 30 s silence-bounded
heartbeat, and a compiled phase's emitStatus/telemetry stream live to
the same reporter instead of being buffered until the run ends (trace
payloads stay excluded, streamed lines are not duplicated into
diagnostics).

Bound the measured 123-minute hang: the Cligent transport aborts an
agent call that observes no adapter event for the configured stall
timeout — stallTimeout config key / SLC_STALL_TIMEOUT, default 600 s,
0 disables — and reports the inactivity duration as a loud phase
failure, with no retry and no interpreted fallback (DR-019).

Co-authored-by: Claude Fable 5 (coder) <cligent@sublang.ai>
An unref'd watchdog timer let Node exit before the inactivity window
elapsed whenever the stalled transport held no I/O of its own: the
process died with an unsettled-await warning instead of reporting the
stall. Reference the timer — it is cleared on every agent event and in
dispose, so it cannot outlive the call it guards.

Caught by driving the built CLI against a transport that emits one
event and then waits forever; the unit test had passed because vitest
holds the loop open. The regression test now asserts the production
timers' ref state directly, since an injected fake bypasses it.

Co-authored-by: Claude Fable 5 (coder) <cligent@sublang.ai>
The "more than ten minutes" estimate was materially optimistic: a
five-line workflow measured over two hours before being abandoned, and
the precompiled demo run — the fast path — took 51 minutes. Replace the
estimates in the README and both demo READMEs with measured ranges,
stated as agent- and workload-dependent, and describe the progress
lines, heartbeat, and stall timeout users now see.

Co-authored-by: Claude Fable 5 (coder) <cligent@sublang.ai>
Two defects found by adversarial review of the watchdog:

A phase that completed inside Cligent's 500 ms post-abort drain was
reported as a stall, discarding a finished — and expensive — phase and
returning a resume token for a session that had succeeded. The observed
outcome now wins over the stall verdict; a genuine hang drains to
`interrupted`, so real stalls are unaffected.

A stall timeout above Node's timer range was accepted, then silently
clamped to 1 ms, aborting every agent call immediately — the exact
inversion of the setting's purpose, reachable by writing milliseconds
where seconds were meant. Both configuration sources now refuse an
out-of-range window.

Also close three test gaps the review confirmed by mutation: progress
liveness was untested (end-of-run buffering passed every assertion),
the bin's compiled-status wiring was untested end-to-end, and the
silence-window reset assertion could not fail.

Co-authored-by: Claude Fable 5 (coder) <cligent@sublang.ai>
Selecting a compiled executor can throw instead of returning a verdict:
the host factory rejects an unmapped pinned Playbook provenance
(PHEXEC-30). That exception unwound past the phase-failure path, so a
run stranded its phase-start line with no terminal event and reported a
bare message with no phase or target — inconsistent with the stale-pin
path, which formats a full report.

Route selection exceptions through the same fail-closed verdict a stale
pin produces, restoring the CLI-4 failure report and closing the CLI-32
progress line. Reproduced end to end: the throw needs a *current* pin,
since a stale one fails before the factory is ever called.

Co-authored-by: Claude Opus 5 (coder) <cligent@sublang.ai>
Co-authored-by: GPT-5.6 Sol (reviewer) <cligent@sublang.ai>
Found while auditing the loop for the same defect class as the reported
selection error, not part of that report. A directory at the linked
path satisfies the DR-003 existence and extension checks, so the read
in the VERIFY-18 import scan is where it surfaces — and an unguarded
throw there also stranded the phase-start line and lost the phase and
target. Treat an unreadable target as the dead artifact it is.

Every started phase now reaches a terminal progress event on every path
through the step loop (CLI-32).

Co-authored-by: Claude Opus 5 (coder) <cligent@sublang.ai>
Co-authored-by: GPT-5.6 Sol (reviewer) <cligent@sublang.ai>
@slalph
slalph force-pushed the fix/4-compile-progress branch from 25fcb5c to 0ee8556 Compare August 1, 2026 15:36
@slalph
slalph merged commit 20a0562 into main Aug 1, 2026
2 checks passed
@slalph
slalph deleted the fix/4-compile-progress branch August 1, 2026 15:55
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

No progress output during compile: silent for 10+ minutes (measured: 2h)

1 participant