The watchdog is blind while the model generates a tool call — Ollama sends ZERO chunks for that entire phase, so Keepalive cannot fire and productive turns are killed #279

Merged

toasterson merged 2 commits from claude/wi-019fb44f-the-watchdog-is-blind-while-the-model-ge into main 2026-07-31 18:12:43 +00:00

Conversation 0 Commits 2 Files changed 2 +342 -63

toasterson commented 2026-07-30 20:49:06 +00:00

Owner

Copy link

Anima work item 019fb44f-27ca-7292-ac94-3892ba166eb9.

MEASURED ROOT CAUSE (2026-07-30) — supersedes the framing below

Ollama sends no chunks at all while the model generates tool-call arguments.
Not "chunks that carry no visible delta" — no chunks. Measured against
https://ollama.com/api/chat, glm-5.2, stream:true, one write_file tool,
prompt asking for ~600 words in the content argument:

46 chunks total, 1233 eval tokens, 7.5s wall
  19:16:41.380 … 41.557   43 thinking deltas   (~180ms, streamed fine)
  19:16:41.557 → 48.434   *** 6.9s, ZERO chunks ***      <-- tool call being generated
  19:16:48.434            1 chunk carrying the ENTIRE tool_calls payload

92% of that generation was total provider silence. The model was working the
whole time.

Why this breaks everything

akh-medu's idle watchdog resets on emitted messages. #276 (merged 302fb347,
deployed as 61c532f3a9ae) added StreamEvent::Keepalive to reset it on any
chunk received — but during tool-call generation there is no chunk to
receive. The keepalive is a no-op for precisely the case that causes the stall.
#276 remains a genuine improvement for the silent-fallback path; it does not
fix this.

Scale it: 600 words of tool argument = 6.9s of silence. A real code edit is
thousands of tokens of content, and a coding agent's most substantial work is
always inside a tool call. The bigger and more useful the edit, the more likely
the turn is killed. That is why every stall logged last_step="narrative" —
narrative is simply the last thing emitted before the model starts producing the
tool call.

This is the mechanism behind the 2026-07-28→29 run: 22 tecton sessions, ~19h,
zero credited work, while the turns were in fact producing complete answers
(8157 and 5898 characters — see Anima WI-430).

Required change

The watchdog must not depend on the provider emitting anything.

1. Heartbeat from the client, not from the stream. While an LLM request is in
   flight, the akh should emit its own liveness on a timer — it knows a request is
   outstanding. Chunk arrival is a provider property and cannot be relied on.
2. Separate the two failure modes. "No bytes on the socket for N seconds" and
   "no request outstanding and nothing emitted for N seconds" are different faults
   and want different timeouts. Today one number conflates them, and the
   legitimate long-tool-call case gets the strictest reading.
3. Never discard completed work. If a turn is killed after the model returned
   a result, that result must still be delivered and scored — today it is
   concatenated onto a stall error and reported outcome=empty.
4. Re-validate #276's Keepalive against this measurement: add a test that a turn
   generating a large tool call survives, since the current one cannot pass.

Acceptance

• A turn whose model spends > idle_secs generating a single large tool call
  completes normally.
• Reproduction test: a prompt forcing a tool call with a very large argument,
  asserting the turn is not killed.
• A killed turn that nonetheless produced output is not scored empty.

---

Original filing (2026-07-30, superseded above but the eliminations still hold)

The turn succeeded and then hung — session
019fb40c-b448-7170-be64-df5e059a0e2c, workspace tecton:

17:23:32  mcp__anima__create_document  → "Adversarial Review — MCP Tools & KG Operations"
17:24:10  mcp__anima__anima_import     → ok, full review imported
17:24:10 → 17:53   ** 29 minutes, zero messages **

Causes eliminated by measurement (do not re-litigate)

1. Not the provider. A long streaming generation from inside akh-thoth
   returned 3611 chunks, max inter-chunk gap 2s.
2. Not quota. Session usage 0% at the time; the probe above succeeded.
3. Not a dead process. The learning daemon logged 4 ticks/minute straight
   through the silence.
4. Not the agent mutex. Same evidence — the daemon takes the same
   Arc<Mutex<Agent>> and kept ticking. (The minute the turn actually worked,
   17:23, has zero daemon ticks and 17:24 shows a catch-up burst of 9 — real
   contention, but not this hang.)
5. Not the streaming fallback. Its System message and Keepalive never fired —
   now explained: no chunks arrive during tool-call generation.

One candidate was checked and cleared: the Arc<ChannelSink> cloned into the
ToolExecutionTracker (mod.rs:754) is torn down correctly by
SessionToolGuard::drop (mod.rs:909).

Related: Anima WI-430 (refusal/empty mislabelling), Anima WI-436 (deliverables
never recorded as Documents).

---

REVIEW ROUND 1 — CHANGES REQUESTED (2026-07-30, PR #278 @ 76b72dfb)

Keep this diff. It is not wrong — it is incomplete, because the root cause was
superseded ~20 minutes after that session was dispatched.

What PR #278 gets right (do not revert)

signal_completion() from the worker, a DrainEvent select in place of relying
on every ChannelSink sender clone being dropped, draining remaining messages
after completion, and a drain_loop_terminates_promptly_when_worker_finishes
test. That closes the "worker finished, drain loop waits until idle_secs" path
structurally, which is exactly what the original brief asked for.

Why it cannot fix the item as now scoped

The dominant failure is not a turn hanging after it finishes — it is a turn
killed while the model is still working. See the measurement in the section
above: 6.9 of 7.5 seconds of a tool-call generation were total provider
silence, zero chunks, then one chunk with the whole tool_calls payload.

Nothing in src/acp/mod.rs can observe a tool call being generated. A change
confined to that file therefore cannot prevent this failure, no matter how
correct it is.

Required to close

1. Client-side heartbeat while a request is in flight. Emit liveness on a
   timer for as long as an LLM request is outstanding, in the
   agentic_chat.rs / ollama.rs layer. The akh knows it has a request open;
   chunk arrival is a provider property we do not control and must not depend on.
2. Split the two timeouts. "No bytes on the socket for N seconds" and "no
   request outstanding and nothing emitted for N seconds" are different faults.
   One idle_secs applies the strictest reading to the legitimate long-tool-call
   case.
3. Stop discarding completed work. A turn killed after its model returned a
   result must still deliver and score that result. 8157 characters of assistant
   output is not outcome=empty.
4. Regression test for the real case: force a tool call with a very large
   argument and assert the turn survives past idle_secs. The #276 Keepalive
   test cannot cover this — it assumes chunks keep arriving.

Verdict entered by hand on the primary DB: the operator PAT lacks
workitem.submit_review, so submit_review_verdict was not callable. The
ci_green completion condition was reset to unmet, since the rejected diff is no
longer certified work — that is what returns the item to the implementer queue.

Anima work item `019fb44f-27ca-7292-ac94-3892ba166eb9`. # MEASURED ROOT CAUSE (2026-07-30) — supersedes the framing below **Ollama sends no chunks at all while the model generates tool-call arguments.** Not "chunks that carry no visible delta" — *no chunks*. Measured against `https://ollama.com/api/chat`, `glm-5.2`, `stream:true`, one `write_file` tool, prompt asking for ~600 words in the `content` argument: ``` 46 chunks total, 1233 eval tokens, 7.5s wall 19:16:41.380 … 41.557 43 thinking deltas (~180ms, streamed fine) 19:16:41.557 → 48.434 *** 6.9s, ZERO chunks *** <-- tool call being generated 19:16:48.434 1 chunk carrying the ENTIRE tool_calls payload ``` **92% of that generation was total provider silence.** The model was working the whole time. ## Why this breaks everything akh-medu's idle watchdog resets on emitted messages. `#276` (merged `302fb347`, deployed as `61c532f3a9ae`) added `StreamEvent::Keepalive` to reset it on **any chunk received** — but during tool-call generation **there is no chunk to receive**. The keepalive is a no-op for precisely the case that causes the stall. `#276` remains a genuine improvement for the silent-fallback path; it does not fix this. Scale it: 600 words of tool argument = 6.9s of silence. A real code edit is thousands of tokens of `content`, and a coding agent's *most substantial* work is always inside a tool call. The bigger and more useful the edit, the more likely the turn is killed. That is why every stall logged `last_step="narrative"` — narrative is simply the last thing emitted before the model starts producing the tool call. This is the mechanism behind the 2026-07-28→29 run: 22 tecton sessions, ~19h, zero credited work, while the turns were in fact producing complete answers (8157 and 5898 characters — see Anima WI-430). ## Required change The watchdog must not depend on the provider emitting anything. 1. **Heartbeat from the client, not from the stream.** While an LLM request is in flight, the akh should emit its own liveness on a timer — it knows a request is outstanding. Chunk arrival is a *provider* property and cannot be relied on. 2. **Separate the two failure modes.** "No bytes on the socket for N seconds" and "no request outstanding and nothing emitted for N seconds" are different faults and want different timeouts. Today one number conflates them, and the legitimate long-tool-call case gets the strictest reading. 3. **Never discard completed work.** If a turn is killed after the model returned a result, that result must still be delivered and scored — today it is concatenated onto a stall error and reported `outcome=empty`. 4. Re-validate `#276`'s Keepalive against this measurement: add a test that a turn generating a large tool call survives, since the current one cannot pass. ## Acceptance - A turn whose model spends > `idle_secs` generating a single large tool call **completes normally**. - Reproduction test: a prompt forcing a tool call with a very large argument, asserting the turn is not killed. - A killed turn that nonetheless produced output is not scored `empty`. --- # Original filing (2026-07-30, superseded above but the eliminations still hold) The turn **succeeded** and then hung — session `019fb40c-b448-7170-be64-df5e059a0e2c`, workspace `tecton`: ``` 17:23:32 mcp__anima__create_document → "Adversarial Review — MCP Tools & KG Operations" 17:24:10 mcp__anima__anima_import → ok, full review imported 17:24:10 → 17:53 ** 29 minutes, zero messages ** ``` ## Causes eliminated by measurement (do not re-litigate) 1. **Not the provider.** A long streaming generation from inside `akh-thoth` returned **3611 chunks, max inter-chunk gap 2s**. 2. **Not quota.** Session usage 0% at the time; the probe above succeeded. 3. **Not a dead process.** The learning daemon logged **4 ticks/minute straight through the silence**. 4. **Not the agent mutex.** Same evidence — the daemon takes the same `Arc<Mutex<Agent>>` and kept ticking. (The minute the turn actually worked, 17:23, has **zero** daemon ticks and 17:24 shows a catch-up burst of 9 — real contention, but not this hang.) 5. **Not the streaming fallback.** Its System message and Keepalive never fired — now explained: no chunks arrive during tool-call generation. One candidate was checked and **cleared**: the `Arc<ChannelSink>` cloned into the `ToolExecutionTracker` (`mod.rs:754`) is torn down correctly by `SessionToolGuard::drop` (`mod.rs:909`). Related: Anima WI-430 (refusal/empty mislabelling), Anima WI-436 (deliverables never recorded as Documents). --- # REVIEW ROUND 1 — CHANGES REQUESTED (2026-07-30, PR #278 @ 76b72dfb) **Keep this diff. It is not wrong — it is incomplete, because the root cause was superseded ~20 minutes after that session was dispatched.** ## What PR #278 gets right (do not revert) `signal_completion()` from the worker, a `DrainEvent` select in place of relying on every `ChannelSink` sender clone being dropped, draining remaining messages after completion, and a `drain_loop_terminates_promptly_when_worker_finishes` test. That closes the "worker finished, drain loop waits until idle_secs" path structurally, which is exactly what the original brief asked for. ## Why it cannot fix the item as now scoped The dominant failure is not a turn hanging *after* it finishes — it is a turn killed *while the model is still working*. See the measurement in the section above: 6.9 of 7.5 seconds of a tool-call generation were **total provider silence**, zero chunks, then one chunk with the whole `tool_calls` payload. Nothing in `src/acp/mod.rs` can observe a tool call being generated. A change confined to that file therefore cannot prevent this failure, no matter how correct it is. ## Required to close 1. **Client-side heartbeat while a request is in flight.** Emit liveness on a timer for as long as an LLM request is outstanding, in the `agentic_chat.rs` / `ollama.rs` layer. The akh knows it has a request open; chunk arrival is a provider property we do not control and must not depend on. 2. **Split the two timeouts.** "No bytes on the socket for N seconds" and "no request outstanding and nothing emitted for N seconds" are different faults. One `idle_secs` applies the strictest reading to the legitimate long-tool-call case. 3. **Stop discarding completed work.** A turn killed after its model returned a result must still deliver and score that result. 8157 characters of assistant output is not `outcome=empty`. 4. **Regression test for the real case**: force a tool call with a very large argument and assert the turn survives past `idle_secs`. The `#276` Keepalive test cannot cover this — it assumes chunks keep arriving. *Verdict entered by hand on the primary DB: the operator PAT lacks `workitem.submit_review`, so `submit_review_verdict` was not callable. The `ci_green` completion condition was reset to unmet, since the rejected diff is no longer certified work — that is what returns the item to the implementer queue.*

toasterson added 1 commit 2026-07-30 20:49:07 +00:00

The watchdog is blind while the model generates a tool call — Ollama sends ZERO chunks for that entire phase, so Keepalive cannot fire and productive turns are killed ... 4696dfd50a

Anima implementation session.

toasterson added 1 commit 2026-07-30 21:42:32 +00:00

Fix watchdog blindness during tool-call generation + preserve completed work ... 0f9f1261b7

Addresses all four requirements from review round 2:

1. **Client-side heartbeat decoupled from provider stream**: Inverted the
   architecture — the blocking socket read now runs in its own thread, and
   the main loop selects over a line channel and a heartbeat channel with
   100ms polling. Heartbeats fire on schedule (every 10s) regardless of
   whether Ollama is sending chunks, fixing the measured 6.9s silence during
   tool-call argument generation.

2. **Separate socket vs application timeouts**: Added `socket_read_timeout`
   field to `AkhAcpAgent` (distinct from `turn_idle_timeout`), with
   `AKH_SOCKET_READ_TIMEOUT_SECS` env var (default 60s). Socket timeout
   detects dead network connections; idle timeout detects application-level
   stalls (blocked locks, unanswered round-trips). The ollama.rs refactor
   makes socket-level timeouts observable via the channel-based architecture.

3. **Preserve completed work when killed**: The stall handler now checks
   `done_rx.try_recv()` before returning `StopReason::Refusal`. If the
   worker finished successfully, remaining queued messages are drained and
   the turn completes normally with `EndTurn`, preventing 8157-character
   responses from being scored as `outcome=empty`.

4. **Test timing assertions**: Updated `long_tool_call_generation_survives_via_heartbeat`
   to track event timestamps and assert at least one Keepalive arrives in
   the [1s, 12s] window DURING the silent phase, not after. The test now
   fails if heartbeats are only delivered post-silence (the broken behavior).

Technical details:
- `ollama.rs`: Spawned separate `reader_thread` and `heartbeat_thread`,
  main loop polls `line_rx` with 100ms timeout and drains `heartbeat_rx`
  every iteration. Removed the blocking `reader.lines()` that prevented
  heartbeat delivery.
- `acp/mod.rs`: Added `socket_read_timeout` field + `socket_read_timeout_from_env()`,
  updated both constructors (`new` + `with_provider`). Stall handler now
  attempts `done_rx.try_recv()` to check worker completion before aborting.

All tests pass, including the regression test that now validates timing.

Co-Authored-By: Claude Sonnet 4.5 <noreply@anthropic.com>

toasterson changed title from WIP: The watchdog is blind while the model generates a tool call — Ollama sends ZERO chunks for that entire phase, so Keepalive cannot fire and productive turns are killed to The watchdog is blind while the model generates a tool call — Ollama sends ZERO chunks for that entire phase, so Keepalive cannot fire and productive turns are killed 2026-07-30 22:16:47 +00:00

toasterson merged commit 53c5b86642 into main 2026-07-31 18:12:43 +00:00

toasterson referenced this pull request from a commit 2026-07-31 18:12:44 +00:00

Merge pull request #279: Client-side heartbeat so a tool-call generation cannot trip the idle watchdog

toasterson referenced this pull request 2026-07-31 20:49:53 +00:00

A turn can receive bytes for 57 minutes and produce nothing — instrument per-request chunks, bytes and tokens so "generating slowly" is distinguishable from "receiving nothing useful" #280

toasterson referenced this pull request 2026-07-31 23:56:30 +00:00

Panic in the turn completion path: tokio oneshot "called after complete" fires once per timed-out turn #282

toasterson referenced this pull request 2026-08-15 21:41:55 +00:00

Sessions on one akh still serialise on the per-workspace Agent mutex, so parallel ACP sessions remain impossible #318

Sign in to join this conversation.

Reviewers

No reviewers

Labels

Clear labels

No items

No labels

Milestone

Clear milestone

No items

No milestone

Projects

Clear projects

No items

No project

Assignees

Clear assignees

No assignees

1 participant

Notifications

Subscribe

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

toasterson/akh-medu!279

No description provided.