mirror of
https://github.com/nexu-io/open-design.git
synced 2026-10-27 09:51:12 +01:00
0918d79fbd
* fix(daemon): make an ACP stage-watchdog stall attributable
An ACP turn that goes silent is ended by attachAcpSession's own stage
watchdog, which fails the turn and then kills the child. Two telemetry
fields that exist to explain that terminal were wrong:
- `last_progress_age_ms` is contractually "near the inactivity ceiling on
a stall". The daemon's ACP `send` wrapper stamped
run.lastAgentActivityAt for every emission, including the watchdog's own
error, so the daemon's timeout event became the last recorded progress
and a 30-minute silence reported 664ms.
- `terminal_trigger` was unset, so the run surfaced only the child's exit
code (AGENT_EXIT_130) - indistinguishable from a user interrupt.
Field case: run 14b04dd3-56b0-4d44-926b-db6cee3017ab (2026-07-28, OD
0.16.1, amr_cloud). 37.2 minutes, killed after ~30 minutes of silence,
reported last_progress_age_ms=664, no terminal_trigger. Triage read that
as "still working when killed" and chased the wrong window.
* fix(daemon): exclude host-synthesized ACP tool pairs from the progress clock
The previous commit stopped the ACP bridge's terminal `error` from stamping
`run.lastAgentActivityAt`, but that is only half the failure path. Every ACP
fatal path calls `flushOpenAcpTools(true)` *before* `send('error')`, and that
helper emits a synthetic `tool_use` + errored `tool_result` pair for each tool
the agent left open. Those ride the ordinary `agent` channel, so they stamped
the progress clock microseconds before the run finalized — a stall that died
with a tool in flight still reported a near-zero `last_progress_age_ms`.
That is the common stall shape, not an edge case: the new regression fixture
(open tool, then a silent stage timeout) reported 605ms against a 2000ms
silence, which is the same magnitude as the field incident's 664ms.
Carry the provenance out-of-band instead of in the payload: `send` takes an
optional `AcpEmissionMeta`, `flushOpenAcpTools` tags its pairs
`hostSynthesized`, and `runtimeEmissionCountsAsAgentProgress` excludes them
alongside the terminal error. The transcript, SSE wire, and Langfuse metadata
are unchanged — the pairs are still emitted, they just no longer count as the
agent making progress.
* test(daemon): name the emission that re-stamps the ACP stall progress clock
The progress-age assertion is green locally and red on CI, and a bare
"expected 16 to be >= 1600" cannot say which emission moved the clock.
Attach the run_finished summary and the persisted run event tail to the
failure so the next CI run identifies the culprit directly.
* fix(daemon): stop the progress clock when the daemon gives up on the turn
CI proved the previous two fixes were still partial. With the failure path's
synthetic tool pairs suppressed, an ACP stall on CI still reported
`last_progress_age_ms` of 17ms and 12ms, and the persisted event tail named the
culprit:
... agent:text_delta, error, agent:diagnostic, diagnostic:runtime_close
Emissions keep arriving AFTER the terminal error. The child's shutdown line on
stderr (`child.stderr.on('data')` stamps every byte), and the diagnostic
promoted from it, both land after the daemon has already decided to kill the
turn — and each one re-stamped the clock, so the reported age measured our own
teardown instead of the agent's silence. That ordering is timing-dependent,
which is why these specs were green locally and red on CI.
Freeze the clock at the verdict instead of hunting emissions one at a time.
`noteAgentActivity` stops advancing `run.lastAgentActivityAt` once this attempt
has a terminal verdict; everything else it does (tool-token TTL, watchdog
re-arm) is unchanged. The freeze is attempt-scoped: retries and the
resume-failed reseed re-enter `startChatRun` with a fresh closure, so the next
attempt measures its own silence. User cancel returns before the freeze and
keeps its own terminal path.
The flushed-tool marker is still required and not redundant: `fail()` flushes
open tools BEFORE it sends the error, so those pairs precede the freeze.
Adds a third regression case: the agent logs to stderr while shutting down.
Without the freeze it reports ~400ms against a 2000ms silence, deterministically.
* docs(daemon): tie the progress-clock predicate and freeze into one rule
* fix(daemon): let the ACP verdict own the attempt's terminal attribution
`freezeProgressClock` stopped the timestamp but left the outer chat inactivity
watchdog armed. `attachAcpSession.fail()` issues one direct SIGTERM and nothing
escalates it, so a child that lingers past the inactivity ceiling lets
`failForInactivity` fire on a run it does not yet consider terminal — the close
handler is what terminalizes — overwriting `terminal_trigger` with
`inactivity_watchdog` and emitting a second failure. The stall then reads as the
wrong clock, which is exactly the confusion `acp_stage_timeout` exists to
remove.
Red spec (a fixture that swallows SIGTERM, with the outer ceiling set just above
the stage timeout) reproduced it deterministically:
AssertionError: expected 'inactivity_watchdog' to be 'acp_stage_timeout'
run event tail: [... "agent:text_delta", "error", "error",
"diagnostic:runtime_close", ...]
Two `error` events, and the run finished under AGENT_EXECUTION_FAILED instead of
the child's own terminal code.
`retireAttemptOnAcpVerdict` now hands the attempt to the close handler under the
verdict the ACP bridge already reached: freeze the clock, retire the outer
watchdog, and escalate the teardown. The escalation is the necessary other half
— retiring the watchdog alone would leave a SIGTERM-ignoring child with nothing
to reap it. `scheduleForcedChildShutdown` captures this attempt's child, so a
retry that swaps `run.child` inside the grace window is unaffected, and user
cancel still returns before any of this.
* fix(daemon): stop every clock of an attempt that already has a verdict
Retiring the outer watchdog at the ACP verdict was not enough on its own.
`noteAgentActivity` only skipped the timestamp when frozen and still fell
through to the timer block, which clears and re-arms `inactivityTimer` — and
the raw `child.stderr` handler routes every late byte through that helper. So a
child that logs its shutdown line while ignoring SIGTERM re-armed the very
watchdog `retireAttemptOnAcpVerdict` had just cleared, and that timer firing
before forced shutdown reaped the child terminalized the run a second time.
The two existing fixtures missed it: one ignores SIGTERM without logging, the
other logs and exits. The gap is a child that does both. With the fixture logging
once (as a real CLI announces shutdown) rather than per signal — repeating it
would keep pushing the timers out and hide the race:
AssertionError: expected 'inactivity_watchdog' to be 'acp_stage_timeout'
run event tail: [... "agent:text_delta", "error", "stderr", "error",
"diagnostic:runtime_close", ...]
`error, stderr, error` is the whole story: the late stderr between the two
verdicts is what re-armed the clock.
`noteAgentActivity` now returns as soon as the attempt is frozen, so neither the
timestamp, the tool-token TTL, nor the watchdog can be restarted by a child that
is already being torn down. The new case also asserts exactly one terminal
`error` reaches the transcript, which is the property the trigger field depends
on.
---------
Co-authored-by: lefarcen <ontf116@gmail.com>