MCP surface wedges permanently while gRPC stays healthy — suspected unbounded outbound Forgejo call under MCP handler serialization (resync_pr_state) #504

New issue

Open

opened 2026-08-06 16:45:40 +00:00 by toasterson · 3 comments

toasterson commented

2026-08-06 16:45:40 +00:00

Owner

Observed 2026-08-06 ~16:39Z on anima-server (pod anima-server-65c4d85cf6-s2bhh, container started 16:23:35Z after a 137 kill of the previous instance).

Symptom

Every POST to /mcp returns 504 upstream timeout (~15s) from the ingress — including a bare initialize with no session. Wedged for 30+ minutes and counting.
/health answers 200 in ~40ms the whole time; gRPC runner traffic (scheduler assignments, register-session) continues normally per server logs.
Server log shows the MCP subsystem's last line at 16:34:46Z (audit.approve_and_merge.merged, Anima PR #500). No MCP request logging after that — later requests never reach handler logging.

Timeline (from the wedged instance's logs + client side)

16:34:46Z — last successful MCP op (approve_and_merge, completed).
16:38:10Z — update_work_item (touch on WI 019fce4c) still succeeded.
~16:39Z — a resync_pr_state call for WI 019fce4c-d90f-7311-aa6c-50dd754f9f29 (PR toasterson/akh-medu#289) timed out client-side; every MCP request since then 504s, including fresh initialize. Forgejo was responding slowly around that time (a list_repo_pull_requests for akh-medu returned 279KB after a long wait).

Hypothesis
resync_pr_state performs an outbound Forgejo read server-side. If that HTTP call has no timeout and MCP handlers serialize on a shared lock/session state, one slow Forgejo response wedges the entire MCP surface permanently — nothing recovers it short of a process restart. Suggested fixes: put a hard timeout on all outbound Forgejo calls made from MCP handlers, and/or stop holding the MCP serialization across outbound I/O.

Related scheduler observations from the same logs (separate but adjacent):

per-executor reservation leak: capped lane reads as full with zero live sessions (executor=tecton, leaked_count=1) — seen at 16:05:33Z and again 16:38:41Z. Each server restart/session death leaks the tecton lane reservation; ready+pinned WIs then sit undispatched until the reconcile heals the counter. This blocked akh-medu WIs 019fce4c/019fce4d for ~20h on 2026-08-05→06.
ready WI unclaimed: project not dispatch-enabled — ~13 illumos-project WIs warned every scheduler tick (age up to 965261s); either enable dispatch for the project or stop queueing them ready.
Churn loops on the claude-code lane: WIs 019f9e06-85c4 ("ContextWindowStats schema"), 019fc826-cf80, 019fa59f-1577 each re-claimed all day producing substantial output without diff — prose is not delivery, classified Empty; no-progress streak tripped but WI has a live session — deferring park repeats without the park ever landing, so the loop never stops.

Previous container exit: code 137 at 16:23:34Z (reason "Error") — worth checking memory limits/liveness separately.

Filed by the akh-medu babysitting session; restarting anima-server to restore MCP service.

Observed 2026-08-06 ~16:39Z on anima-server (pod anima-server-65c4d85cf6-s2bhh, container started 16:23:35Z after a 137 kill of the previous instance). **Symptom** - Every POST to `/mcp` returns 504 upstream timeout (~15s) from the ingress — including a bare `initialize` with no session. Wedged for 30+ minutes and counting. - `/health` answers 200 in ~40ms the whole time; gRPC runner traffic (scheduler assignments, register-session) continues normally per server logs. - Server log shows the MCP subsystem's **last line at 16:34:46Z** (`audit.approve_and_merge.merged`, Anima PR #500). No MCP request logging after that — later requests never reach handler logging. **Timeline (from the wedged instance's logs + client side)** - 16:34:46Z — last successful MCP op (approve_and_merge, completed). - 16:38:10Z — `update_work_item` (touch on WI 019fce4c) still succeeded. - ~16:39Z — a `resync_pr_state` call for WI 019fce4c-d90f-7311-aa6c-50dd754f9f29 (PR toasterson/akh-medu#289) timed out client-side; every MCP request since then 504s, including fresh `initialize`. Forgejo was responding slowly around that time (a `list_repo_pull_requests` for akh-medu returned 279KB after a long wait). **Hypothesis** `resync_pr_state` performs an outbound Forgejo read server-side. If that HTTP call has no timeout and MCP handlers serialize on a shared lock/session state, one slow Forgejo response wedges the entire MCP surface permanently — nothing recovers it short of a process restart. Suggested fixes: put a hard timeout on all outbound Forgejo calls made from MCP handlers, and/or stop holding the MCP serialization across outbound I/O. **Related scheduler observations from the same logs (separate but adjacent):** 1. `per-executor reservation leak: capped lane reads as full with zero live sessions` (executor=tecton, leaked_count=1) — seen at 16:05:33Z and again 16:38:41Z. Each server restart/session death leaks the tecton lane reservation; ready+pinned WIs then sit undispatched until the reconcile heals the counter. This blocked akh-medu WIs 019fce4c/019fce4d for ~20h on 2026-08-05→06. 2. `ready WI unclaimed: project not dispatch-enabled` — ~13 illumos-project WIs warned every scheduler tick (age up to 965261s); either enable dispatch for the project or stop queueing them ready. 3. Churn loops on the claude-code lane: WIs 019f9e06-85c4 ("ContextWindowStats schema"), 019fc826-cf80, 019fa59f-1577 each re-claimed all day producing `substantial output without diff — prose is not delivery, classified Empty`; `no-progress streak tripped but WI has a live session — deferring park` repeats without the park ever landing, so the loop never stops. Previous container exit: code 137 at 16:23:34Z (reason "Error") — worth checking memory limits/liveness separately. Filed by the akh-medu babysitting session; restarting anima-server to restore MCP service.

toasterson commented

2026-08-06 17:26:36 +00:00

Author

Owner

Recurred within ~15 minutes on a fresh pod — this is not a one-off and my resync_pr_state was not the (only) trigger.

Timeline, second occurrence:

~17:03Z — new pod anima-server-78bfd64d46-fn8sr came up (new ReplicaSet hash, so likely a Flux-applied newer image after today's Anima merges, replacing the pod from my 16:47Z rollout restart).
17:05:49Z, 17:08:07Z — MCP resync_pr_state ops served fine (Anima PRs #485/#481 hand-rebase resyncs, actor 019d8deb).
17:11:25Z — MCP op closed live sessions on implementation complete (WI 019f90cd, akh-medu Release Alpha).
≤17:26Z — /mcp 504s again on bare initialize (~15s at the ingress). No MCP log lines after 17:11:25. /health + gRPC scheduler traffic still healthy.

Pattern across both wedges: a handful of MCP ops that do outbound Forgejo I/O (resync, audit/merge, session-close) complete, then the surface hardlocks with no further request logging. Consistent with a poisoned/never-released lock or an exhausted single-worker MCP executor rather than one specific slow call.

Restarting via pod delete this time (rollout-restart annotations appear to get reverted by GitOps reconciliation).

**Recurred within ~15 minutes on a fresh pod — this is not a one-off and my `resync_pr_state` was not the (only) trigger.** Timeline, second occurrence: - ~17:03Z — new pod `anima-server-78bfd64d46-fn8sr` came up (new ReplicaSet hash, so likely a Flux-applied newer image after today's Anima merges, replacing the pod from my 16:47Z rollout restart). - 17:05:49Z, 17:08:07Z — MCP `resync_pr_state` ops served fine (Anima PRs #485/#481 hand-rebase resyncs, actor 019d8deb). - 17:11:25Z — MCP op `closed live sessions on implementation complete` (WI 019f90cd, akh-medu Release Alpha). - ≤17:26Z — `/mcp` 504s again on bare `initialize` (~15s at the ingress). No MCP log lines after 17:11:25. `/health` + gRPC scheduler traffic still healthy. Pattern across both wedges: a handful of MCP ops that do outbound Forgejo I/O (resync, audit/merge, session-close) complete, then the surface hardlocks with no further request logging. Consistent with a poisoned/never-released lock or an exhausted single-worker MCP executor rather than one specific slow call. Restarting via pod delete this time (rollout-restart annotations appear to get reverted by GitOps reconciliation).

toasterson commented

2026-08-06 18:34:04 +00:00

Author

Owner

Corroborating correlation for the MCP wedge — akh-gateway dispatch.

akh-medu WI 019fbf62 (Phase 44n) now carries an operator-hold park reason: "dispatch to akh-gateway wedges anima-server (2026-08-06); unpark after gateway recycle verified". The timing lines up with both wedges I logged here:

Wedge #1 (~16:39Z): Release Alpha tecton sessions were being dispatched/reconciled through the akh gateway at 16:36–16:38 (sessions 019fd7ee → 019fd7f0).
Wedge #2 (≤17:26Z, last MCP log 17:11:25): Phase 44n's tecton session 019fd80f ran 17:11:30–17:30:42 and failed; the wedge window opens exactly at its dispatch.

So the trigger may not be MCP-handler outbound Forgejo I/O after all (or not only that) — a dispatch/attach to the akh-gateway (anima-akh-gateway-thoth on archibald) that hangs appears able to take the MCP surface down with it while gRPC scheduling continues. Worth checking what shared state (lock/executor) the gateway-dispatch path and the MCP layer contend on.

Live counter-datapoint: thoth-lane dispatch of akh-medu WI 019fa83d at 18:18:37Z succeeded (session running, PR #294 opened) with MCP staying healthy — so it's not every gateway dispatch, plausibly only ones that hang.

**Corroborating correlation for the MCP wedge — akh-gateway dispatch.** akh-medu WI 019fbf62 (Phase 44n) now carries an operator-hold park reason: *"dispatch to akh-gateway wedges anima-server (2026-08-06); unpark after gateway recycle verified"*. The timing lines up with both wedges I logged here: - Wedge #1 (~16:39Z): Release Alpha tecton sessions were being dispatched/reconciled through the akh gateway at 16:36–16:38 (sessions 019fd7ee → 019fd7f0). - Wedge #2 (≤17:26Z, last MCP log 17:11:25): Phase 44n's tecton session 019fd80f ran 17:11:30–17:30:42 and **failed**; the wedge window opens exactly at its dispatch. So the trigger may not be MCP-handler outbound Forgejo I/O after all (or not only that) — a dispatch/attach to the akh-gateway (anima-akh-gateway-thoth on archibald) that hangs appears able to take the MCP surface down with it while gRPC scheduling continues. Worth checking what shared state (lock/executor) the gateway-dispatch path and the MCP layer contend on. Live counter-datapoint: thoth-lane dispatch of akh-medu WI 019fa83d at 18:18:37Z succeeded (session running, PR #294 opened) with MCP staying healthy — so it's not every gateway dispatch, plausibly only ones that hang.

toasterson commented

2026-08-06 20:43:00 +00:00

Author

Owner

Gateway attach-stream death confirmed as the akh-lane blocker (and the recycle fixes it).

After today's repeated anima-server pod replacements (2 crash/wedge restarts + at least 2 Flux image rolls), the akh gateway's runner (019f2f96, advertises tecton+thoth) stopped re-attaching entirely — 30+ minutes of complete log silence in anima-akh-gateway-thoth-1 while the other two runners re-attached to each new pod within seconds. Result: both akh lanes dead, ready+pinned WIs unclaimed indefinitely, no scheduler warning names this condition (the lanes just silently vanish from dispatch).

docker restart anima-akh-gateway-thoth-1 at 20:41:45Z fixed it instantly: attach + hello + both akhs advertised within 200ms, and both stalled akh-medu WIs (019fa83d thoth, 019fce4c tecton corrective-resume) were assigned 23 seconds later.

Suggested hardening: (1) the gateway's attach loop should reconnect with backoff forever like the other runners evidently do — whatever state kills its stream after repeated server bounces needs a supervisor; (2) the scheduler should WARN when a pinned-executor lane has ready work but the advertising runner hasn't attached since boot — today that condition was only inferable by elimination.

(Also for the record on this issue's earlier thread: the 20:10:38Z rebind-window abandonment of both akh sessions traces to the 19:58–20:01 disk-full outage on archibald — root disk hit 100%, Forgejo Postgres crash-looped, fixed by freeing 111GB. Separate incident, same evening.)

**Gateway attach-stream death confirmed as the akh-lane blocker (and the recycle fixes it).** After today's repeated anima-server pod replacements (2 crash/wedge restarts + at least 2 Flux image rolls), the akh gateway's runner (`019f2f96`, advertises tecton+thoth) stopped re-attaching entirely — 30+ minutes of complete log silence in `anima-akh-gateway-thoth-1` while the other two runners re-attached to each new pod within seconds. Result: both akh lanes dead, ready+pinned WIs unclaimed indefinitely, no scheduler warning names this condition (the lanes just silently vanish from dispatch). `docker restart anima-akh-gateway-thoth-1` at 20:41:45Z fixed it instantly: attach + hello + both akhs advertised within 200ms, and both stalled akh-medu WIs (019fa83d thoth, 019fce4c tecton corrective-resume) were assigned 23 seconds later. Suggested hardening: (1) the gateway's attach loop should reconnect with backoff forever like the other runners evidently do — whatever state kills its stream after repeated server bounces needs a supervisor; (2) the scheduler should WARN when a pinned-executor lane has ready work but the advertising runner hasn't attached since boot — today that condition was only inferable by elimination. (Also for the record on this issue's earlier thread: the 20:10:38Z rebind-window abandonment of both akh sessions traces to the 19:58–20:01 disk-full outage on archibald — root disk hit 100%, Forgejo Postgres crash-looped, fixed by freeing 111GB. Separate incident, same evening.)