toasterson/akh-medu

Watch

Fork 0

WIP: A turn goes silent after its work is done and only ends at the idle watchdog — provider, quota, process health and the agent mutex are all excluded #278

Draft

toasterson wants to merge 1 commit from claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don into main

toasterson commented

2026-07-30 18:54:48 +00:00

Owner

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

What was measured, 2026-07-30, workspace `tecton`, session `019fb40c-b48c-7413-9231-79363b0f6f3f`

The turn succeeded and then hung.

17:22:39  session.started
17:23:27  agent_thought — reads the task
17:23:32  mcp__anima__create_document  → 019fb40d-7a0d… "Adversarial Review — MCP Tools & KG Operations"
17:23:36  mcp__anima__update_document  → ok
17:23:40  file_io  — reads docs/ai/reviews/2026-07-24-mcp-tools-kg-operations…
17:24:10  mcp__anima__anima_import     → ok, full review imported
17:24:10 → 17:53   ** 29 minutes, zero messages **   (cut short only because an
                    operator recreated the gateway; the 2700s watchdog would
                    have fired at ~18:09)

The deliverable was complete at 17:24:10. Everything after that is dead air.
This is the same shape as the 19 stalls of 2026-07-29 — all ending at exactly
idle_secs, all last_step="narrative" — but here the useful work demonstrably
finished first, which makes the window much easier to reason about.

Causes eliminated by measurement (do not re-litigate these)

Not the provider. A long streaming generation issued from inside
akh-thoth during this investigation returned 3611 chunks with a maximum
inter-chunk gap of 2 seconds:
curl -N .../api/chat -d '{"model":"glm-5.2","stream":true,"think":"high",…}'.
ollama.com streams long high-thinking generations fine.
Not quota. Session usage 0% at the time (weekly 92.1%, but requests
succeed — the probe above is proof).
Not a dead process. The background learning daemon logged
trigger "learn-on-new-triples" at a steady 4 ticks/minute straight through
the silence (17:25 … 17:53, unbroken). The daemon takes the same
Arc<Mutex<Agent>>, so the process was alive and acquiring that lock.
Not the agent mutex being held by the turn. Same evidence: the daemon
could not have ticked if the turn held the lock. Note the converse detail —
the minute the turn was actually working (17:23) has zero daemon
ticks, and 17:24 shows a catch-up burst of 9. That is real contention
(see the parallel-sessions work item), but it is not what causes this hang.
Not the streaming fallback. The merged fix for that is deployed (akhomed
image 61c532f3a9ae, built from 222b2f1). Its streaming failed … continuing non-streaming System message and its StreamEvent::Keepalive
heartbeat both never fired. No chunk arrived, so no keepalive: whatever
the turn is waiting on, it is not a slow provider response.

What that leaves

The turn's messages stop, the process is healthy, the lock is free, and the drain
loop in src/acp/mod.rs (~3590) sits in tokio::time::timeout(idle, msg_rx.recv()) until the watchdog. Either the worker finished and the
ChannelSink's sender was never dropped (so recv() never yields None), or
the worker is parked on something that issues no request at all.

One candidate was checked and cleared: the Arc<ChannelSink> cloned into the
ToolExecutionTracker (mod.rs:754) is torn down correctly —
SessionToolGuard::drop (mod.rs:909) calls clear_tool_tracker(). If a
surviving sender is the cause, it is a different clone — look for ones captured
by session-scoped MCP proxy tools or by spawned tasks, which would outlive the
guard.

Required change

Instrument the boundary. Log when the turn worker returns, and separately
when the drain loop observes the channel close. Today those two events are
indistinguishable in the log, which is why this took a day to corner. If the
worker returns and the channel does not close within a second, that is the bug,
and it should say so loudly.
Make the channel closure structural. The drain loop's termination must not
depend on every clone of a sender being dropped on every path. Prefer an
explicit completion signal from the worker (a oneshot, or a sentinel message)
that the loop selects on alongside msg_rx.
Then fix whatever the instrumentation names.

Acceptance

A turn that completes its work ends within seconds, not at idle_secs.
A test asserts the drain loop terminates promptly when the worker returns, even
if a sender clone is still alive.
The daemon log distinguishes "worker returned" from "channel closed".

Why this is the top item

Every long akh turn dies this way. On 2026-07-29 that was 22 sessions and zero
delivered work across 19 hours. The work is often already done when the turn is
killed, and the runner then scores an empty outcome and re-dispatches — so this
one defect manufactures both the throughput loss and a large share of the false
parks.

Anima work item `019fb44f-27ca-7292-ac94-3892ba166eb9`. ## What was measured, 2026-07-30, workspace `tecton`, session `019fb40c-b48c-7413-9231-79363b0f6f3f` The turn **succeeded** and then hung. ``` 17:22:39 session.started 17:23:27 agent_thought — reads the task 17:23:32 mcp__anima__create_document → 019fb40d-7a0d… "Adversarial Review — MCP Tools & KG Operations" 17:23:36 mcp__anima__update_document → ok 17:23:40 file_io — reads docs/ai/reviews/2026-07-24-mcp-tools-kg-operations… 17:24:10 mcp__anima__anima_import → ok, full review imported 17:24:10 → 17:53 ** 29 minutes, zero messages ** (cut short only because an operator recreated the gateway; the 2700s watchdog would have fired at ~18:09) ``` The deliverable was complete at 17:24:10. Everything after that is dead air. This is the same shape as the 19 stalls of 2026-07-29 — all ending at exactly `idle_secs`, all `last_step="narrative"` — but here the useful work demonstrably finished first, which makes the window much easier to reason about. ## Causes eliminated by measurement (do not re-litigate these) 1. **Not the provider.** A long streaming generation issued from inside `akh-thoth` during this investigation returned **3611 chunks with a maximum inter-chunk gap of 2 seconds**: `curl -N .../api/chat -d '{"model":"glm-5.2","stream":true,"think":"high",…}'`. ollama.com streams long high-thinking generations fine. 2. **Not quota.** Session usage 0% at the time (weekly 92.1%, but requests succeed — the probe above is proof). 3. **Not a dead process.** The background learning daemon logged `trigger "learn-on-new-triples"` at a steady **4 ticks/minute straight through the silence** (17:25 … 17:53, unbroken). The daemon takes the same `Arc<Mutex<Agent>>`, so the process was alive *and* acquiring that lock. 4. **Not the agent mutex being held by the turn.** Same evidence: the daemon could not have ticked if the turn held the lock. Note the converse detail — the minute the turn was actually working (**17:23**) has **zero** daemon ticks, and 17:24 shows a catch-up burst of 9. That is real contention (see the parallel-sessions work item), but it is not what causes this hang. 5. **Not the streaming fallback.** The merged fix for that is deployed (akhomed image `61c532f3a9ae`, built from `222b2f1`). Its `streaming failed … continuing non-streaming` System message and its `StreamEvent::Keepalive` heartbeat **both never fired**. No chunk arrived, so no keepalive: whatever the turn is waiting on, it is not a slow provider response. ## What that leaves The turn's messages stop, the process is healthy, the lock is free, and the drain loop in `src/acp/mod.rs` (~3590) sits in `tokio::time::timeout(idle, msg_rx.recv())` until the watchdog. Either the worker finished and the `ChannelSink`'s sender was never dropped (so `recv()` never yields `None`), or the worker is parked on something that issues no request at all. One candidate was checked and **cleared**: the `Arc<ChannelSink>` cloned into the `ToolExecutionTracker` (`mod.rs:754`) is torn down correctly — `SessionToolGuard::drop` (`mod.rs:909`) calls `clear_tool_tracker()`. If a surviving sender is the cause, it is a *different* clone — look for ones captured by session-scoped MCP proxy tools or by spawned tasks, which would outlive the guard. ## Required change 1. **Instrument the boundary.** Log when the turn worker returns, and separately when the drain loop observes the channel close. Today those two events are indistinguishable in the log, which is why this took a day to corner. If the worker returns and the channel does not close within a second, that is the bug, and it should say so loudly. 2. **Make the channel closure structural.** The drain loop's termination must not depend on every clone of a sender being dropped on every path. Prefer an explicit completion signal from the worker (a oneshot, or a sentinel message) that the loop selects on alongside `msg_rx`. 3. Then fix whatever the instrumentation names. ## Acceptance - A turn that completes its work ends **within seconds**, not at `idle_secs`. - A test asserts the drain loop terminates promptly when the worker returns, even if a sender clone is still alive. - The daemon log distinguishes "worker returned" from "channel closed". ## Why this is the top item Every long akh turn dies this way. On 2026-07-29 that was 22 sessions and zero delivered work across 19 hours. The work is often already done when the turn is killed, and the runner then scores an empty outcome and re-dispatches — so this one defect manufactures both the throughput loss and a large share of the false parks.

toasterson added 1 commit

2026-07-30 18:54:48 +00:00

A turn goes silent after its work is done and only ends at the idle watchdog — provider, quota, process health and the agent mutex are all excluded

CI / publish-chart (pull_request) Successful in 11m6s

Details

CI / publish-chart (push) Successful in 11m24s

Details

CI / check-seshat (pull_request) Successful in 13m25s

Details

CI / check-seshat (push) Successful in 13m32s

Details

CI / docker-seshd (pull_request) Successful in 18m48s

Details

CI / docker-seshd (push) Successful in 18m47s

Details

76b72dfbf3

Anima implementation session.

toasterson referenced this pull request

2026-07-30 20:49:06 +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 #279

CI / publish-chart (pull_request) Successful in 11m6s

Details

CI / publish-chart (push) Successful in 11m24s

Details

CI / check-seshat (pull_request) Successful in 13m25s

Details

CI / check-seshat (push) Successful in 13m32s

Details

CI / docker-seshd (pull_request) Successful in 18m48s

Details

CI / docker-seshd (push) Successful in 18m47s

Details

This pull request has changes conflicting with the target branch.

src/acp/mod.rs

View command line instructions

Manual merge helper

Use this merge commit message when completing the merge manually.

Merge commit title

Merge pull request 'WIP: A turn goes silent after its work is done and only ends at the idle watchdog — provider, quota, process health and the agent mutex are all excluded' (#278) from claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don into main

Merge commit body

Reviewed-on: https://code.aopc.cloud/toasterson/akh-medu/pulls/278

Merge pull request 'WIP: A turn goes silent after its work is done and only ends at the idle watchdog — provider, quota, process health and the agent mutex are all excluded' (#278) from claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don into main

Reviewed-on: https://code.aopc.cloud/toasterson/akh-medu/pulls/278

Checkout

From your project repository, check out a new branch and test the changes.

git fetch -u origin claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don:claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

Merge

Merge the changes and update on Forgejo.

Warning: The "Autodetect manual merge" setting is not enabled for this repository, you will have to mark this pull request as manually merged afterwards.

git switch main

git merge --no-ff claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git rebase main

git switch main

git merge --ff-only claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git rebase main

git switch main

git merge --no-ff claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch main

git merge --squash claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch main

git merge --ff-only claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git switch main

git merge claude/wi-019fb44f-a-turn-goes-silent-after-its-work-is-don

git push origin main

No reviewers

No labels

No milestone

No project

No assignees

1 participant

Notifications

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!278

No description provided.

Rows
Columns

WIP: A turn goes silent after its work is done and only ends at the idle watchdog — provider, quota, process health and the agent mutex are all excluded #278

What was measured, 2026-07-30, workspace tecton, session 019fb40c-b48c-7413-9231-79363b0f6f3f

Causes eliminated by measurement (do not re-litigate these)

What that leaves

Required change

Acceptance

Why this is the top item

Manual merge helper

Checkout

Merge

What was measured, 2026-07-30, workspace `tecton`, session `019fb40c-b48c-7413-9231-79363b0f6f3f`