From c4bd9427facd1015a31eff84a7e6ad950371919b Mon Sep 17 00:00:00 2001 From: leel Date: Mon, 13 Jul 2026 19:15:26 +0800 Subject: [PATCH] fix(claude): resolve queue-operation prompt completion deadlock When a prompt is delivered via tmux paste-buffer while the Claude REPL is busy (cooking/tool_use), Claude CLI records it as a 'type=queue-operation, operation=enqueue, content=' entry (optionally followed later by an attachment/queued_command), and does NOT synthesize a 'type=user' message. The completion pipeline was blind to queue-operation records: structured_event() dropped them entirely, so handle_user_event() never saw the CCB_REQ_ID anchor, anchor_seen stayed False, assistant events (including the final end_turn and the last_assistant_uuid needed for turn_duration matching) were gated out, and the attempt hung in 'running' forever, backing up the mailbox queue. This manifested in the field as repeated pm (central dispatcher) stalls because pm is the agent that most often receives async replies while busy. A 183-job sample of the pm session log found 14 queue-op prompt deliveries; 9 of them failed to complete automatically (7 incomplete, 2 cancelled by human recovery). Fix: 1. structured_event() now synthesizes a role=user event from queue-operation/enqueue records carrying the full prompt text, so the anchor (CCB_REQ_ID) is observed and anchor_seen flips. 2. structured_event() also emits zero-text assistant events for assistant entries whose content is pure tool_use/thinking blocks (previously dropped because extract_message yields no visible text). These carry the assistant uuid so that pre-anchor bookkeeping can track last_assistant_uuid and the later turn_duration system event's parent_uuid matches. 3. _process_event() runs a pre-anchor bookkeeping pass on every assistant event (uuid tracking only) before the anchor_seen gate; full chunk/reply/turn-boundary handling still requires anchor_seen. A detailed diagnosis is in docs/claude-queue-operation-completion-deadlock-diagnosis.md. Verified: - All 14 historical queue-op stuck jobs (sampled from the pm session) now reach TURN_BOUNDARY under the patched detector. - idle-REPL (user/text_string) path is unchanged; regression on normal prompts passes. - Existing claude parsing/event_reading/exec_polling/assistant_events tests still pass (19/19). --- ...operation-completion-deadlock-diagnosis.md | 183 ++++++++++++++++++ .../parsing_runtime/structured.py | 75 +++++++ .../claude/execution_runtime/polling.py | 79 +++++++- 3 files changed, 335 insertions(+), 2 deletions(-) create mode 100644 docs/claude-queue-operation-completion-deadlock-diagnosis.md diff --git a/docs/claude-queue-operation-completion-deadlock-diagnosis.md b/docs/claude-queue-operation-completion-deadlock-diagnosis.md new file mode 100644 index 000000000..d936f7d94 --- /dev/null +++ b/docs/claude-queue-operation-completion-deadlock-diagnosis.md @@ -0,0 +1,183 @@ +# Claude `queue-operation` Prompt 完成检测死锁 · 根因诊断 + +Date: 2026-07-13 +Version observed: ccb 8.0.19 (`60b3c3d`) +Provider impacted: claude (`session_boundary` completion, no BEGIN/DONE wrapping) +Symptom agent in observed run: `pm` (the central coordinator, highest async-reply fan-in, deadlocks ~5 times/day) + +## 1. TL;DR + +Claude Code CLI has two ways to record a prompt submitted via tmux paste-buffer into the session JSONL: + +| REPL state when prompt arrives | entry in session JSONL | CCB structured_event parses it? | +|---|---|---| +| Idle at `❯` prompt | `{"type":"user","message":{"role":"user","content":...}}` | yes | +| Busy (cooking / tool_use / assistant turn) | `{"type":"queue-operation","operation":"enqueue","content":...}` + later `{"type":"attachment","attachment":{"type":"queued_command",...}}` | **no — dropped on the floor** | + +When the prompt lands as `queue-operation`: + +1. `handle_user_event()` never fires → `poll.anchor_seen` stays `False` forever. +2. `poll_submission._process_event` short-circuits: `if role == "assistant" and poll.anchor_seen: handle_assistant_event(...)` → assistant events stop being ingested entirely. +3. `maybe_append_assistant_end_turn_boundary` returns early on `not poll.anchor_seen`. +4. `last_assistant_uuid` is never updated, so `is_turn_boundary_event(turn_duration)` hits `if not last_assistant_uuid: return False` and the real turn boundary (which *does* exist in the log as `subtype:"turn_duration"`) is ignored. +5. `session_boundary` claude prompts use `wrap_claude_turn_prompt` (no CCB_BEGIN/CCB_DONE markers), so the text-based `maybe_append_turn_boundary(is_done_text(...))` fallback also can't fire. +6. The attempt stays `running`, the mailbox head stays `delivering`, all subsequent `task_reply`s queue up behind it, and the agent appears frozen until a human `ccb clear`/`ccb restart`. + +## 2. Evidence + +### 2.1 Runtime snapshot (project `MiniMES`, pm stuck job `job_006fe7f3bdad`) + +- ccbd: healthy, generation 29, heartbeat fresh, fault list empty. +- pm mailbox: `state=delivering`, `queue_depth=5`, `pending_reply_count=4`, head event `iev_f9faa3fd62f9` delivering since 09:57:20Z (≈47 min at time of diagnosis). +- Queued behind the head: 4 `task_reply`s (from gate, agent1, agent2) that never get processed. +- All other agents idle. +- pm pane text: the turn actually finished — assistant emitted `三条并行在跑: agent1(is_qc 调查) + agent2(archi 终验) + gate 回执`, then `turn_duration 117037ms`, then `away_summary`, then the `❯` prompt. +- pm session JSONL ends with exactly the expected completion sequence: `assistant(stop_reason=end_turn, uuid=8a6a7...) → system(turn_duration, parentUuid=8a6a7...) → system(away_summary) → last-prompt`. +- ccbd persisted execution state for the job (`executions/job_006fe7f3bdad.json`): `status=incomplete, reason=in_progress, state.offset=30707195` — offset has advanced to end-of-file, no terminal decision recorded. + +### 2.2 Quantitative: how often the bad path fires + +Scanning the entire pm session log (`de07c1c5-…jsonl`, 10665 entries, 183 CCB jobs): + +- Entry types carrying `CCB_REQ_ID:` — + - `last-prompt`: 483 (meta, not data) + - `user/text_string`: 175 (normal path) + - `queue-op/enqueue`: **14** (bad path) + - `user/tool_result`: 12 (CCB_REQ_ID appears inside a tool-result string, i.e. subagent mentions, not our prompt) + - `attachment/queued_command`: 9 (companion to queue-op) + - `attachment/file`: 8 +- First entry per job (the path CCB first sees the anchor via): + - `user/text_string`: 160 — these complete normally. + - `queue-op/enqueue`: **14** — these hit the deadlock. + - `user/tool_result`: 9 (secondary references inside tool output, not anchor carriers). + +Attempt-state history for the 14 queue-op jobs from `ccbd/attempts/attempts.jsonl`: + +| job_id | states | outcome | +|---|---|---| +| job_a4fdbb39ef03 | pending→running→incomplete | deadlocked, timed out | +| job_abc2a6f0e759 | pending→running→incomplete | deadlocked | +| job_ac6c57ed0ccb | pending→running→incomplete | deadlocked | +| job_bacfdca6a8f0 | pending→running→completed | lucky (pm happened to re-echo anchor text? fallback?) | +| job_ca6350bfe4b9 | pending→running→incomplete | deadlocked (pane-crash log shows pm confused about how to reply) | +| job_d634fca7b17f | pending→running→completed | lucky | +| job_1b6b0e0b6d7b | pending→running→completed | lucky | +| job_5db11acfa941 | pending→running→cancelled | human recovery | +| job_0410ed6e216d | pending→running→cancelled | human recovery | +| job_7e1630c61912 | pending→running→completed | lucky | +| job_80e20e2ec2d6 | pending→running→incomplete | deadlocked | +| job_f1657ae7f198 | pending→running→incomplete | deadlocked | +| job_cd4f813fc5c2 | pending→running→incomplete | deadlocked (previous jam today) | +| job_006fe7f3bdad | pending→running | **current jam** | + +→ 9 out of 14 queue-op prompt deliveries failed to complete automatically; the 4 "completed" ones likely closed via non-anchor paths (e.g. pm output CCB_DONE by coincidence after subagent replies, or were rescued by later prompt injections). There is no reliable self-recovery. + +### 2.3 Code trail (main branch `60b3c3d`) + +- `lib/provider_backends/claude/comm_runtime/parsing_runtime/structured.py:8-53` + `structured_event()` only recognizes `type ∈ {user, assistant, system}`. `queue-operation` and `attachment` are not handled and yield `None`, so they never become events. +- `lib/provider_backends/claude/execution_runtime/state_machine_runtime/system_events.py:19-35` + `handle_user_event()` is the only site that sets `poll.anchor_seen = True`; it fires only on `role == "user"` events and only when `f"{REQ_ID_PREFIX} {poll.request_anchor}" in text`. +- `lib/provider_backends/claude/execution_runtime/polling.py:302-304` + ```python + if role == "assistant" and poll.anchor_seen: + handle_assistant_event(submission, poll, event, now=now) + ``` + Assistant events are ignored entirely before the anchor is seen. +- `lib/provider_backends/claude/execution_runtime/state_machine_runtime/assistant_events_runtime.py:169-173` + ```python + if poll.reached_turn_boundary: return + if is_subagent or not poll.anchor_seen or not poll.request_anchor: return + if assistant_stop_reason(event) != "end_turn": return + ``` + End-of-turn via assistant `stop_reason=end_turn` requires anchor_seen. +- `lib/provider_backends/claude/execution_runtime/event_reading_runtime/turns.py:4-12` + ```python + if entry_type != "system" or subtype != "turn_duration": return False + if not last_assistant_uuid: return False + return parent_uuid == last_assistant_uuid + ``` + `last_assistant_uuid` is only set by `append_chunk_item` in `assistant_events_runtime.py:94`, which sits behind the same `poll.anchor_seen` gate. So it stays empty and the turn_duration boundary is discarded. +- `lib/provider_backends/claude/protocol_runtime/prompt.py:20-22` + `wrap_claude_turn_prompt()` (used for `session_boundary` providers when a completion dir is registered) emits only `CCB_REQ_ID: \n\n` — no CCB_BEGIN/CCB_DONE pair. The text-marker fallback in `maybe_append_turn_boundary(is_done_text(...))` therefore cannot close the turn either. +- `lib/provider_hooks/artifacts_runtime/transcript.py:219-227` + There *is* explicit handling for `queue-operation` records in the offline artifact transcript code: + ```python + def _queue_operation_text(record): + if str(record.get('type') or '').strip().lower() != 'queue-operation': return None + return str(record.get('content') or '') + ``` + This proves the record type is known to CCB, but the handling never made it into the live completion-detection pipeline. + +### 2.4 Why pm is the most visible victim + +- pm is the dispatch hub; almost every gate reply and subagent completion is routed back to pm. +- pm is almost never idle (it is constantly dispatching, reading tool results, sending `ask --silence`, etc.), so when CCB injects a new message via tmux paste-buffer, Claude REPL is almost always busy → the prompt *consistently* lands as `queue-operation`. +- Other claude agents (agent2, agent6) are lower-throughput; their prompts more often arrive at idle REPL → `user/text_string` → normal completion. +- Other providers (codex, kimi, opencode) use different completion detectors (`protocol_turn` for codex; native turn-log polling for kimi; etc.) and are not on this code path. + +## 3. Root causes (two compounding defects) + +### Defect A — Parser blind spot (primary) +`structured_event()` does not synthesize a synthetic `role=user` event from `type=queue-operation` records whose `content` contains the prompt text. The anchor text is *physically present* in the JSONL (in the `content` field) but never converted into an event, so the rest of the state machine has no idea the prompt was delivered. + +### Defect B — No upper-bound watchdog (secondary, amplifies A into a user-visible hang) +Once a submission is `prompt_sent=true`, there is no attempt-level timeout/watchdog that forces the attempt to a terminal state (`failed` / `incomplete` with diagnostic `turn_boundary_timeout`) if no completion decision is produced after N seconds. The only timeout in the loop is `ready_timeout_s` (8 s) which gates prompt *dispatch*, not completion. + +Without B, defect A causes silent indefinite deadlock instead of a loud, diagnostic, recoverable failure. + +## 4. Additional robustness gaps observed + +1. **`anchor_seen` is monotonic within a poll but never cross-validated against session-log offset.** If the parser misses the anchor on first pass (because it was a queue-op), it will never look backward for it. +2. **Assistant events before anchor are fully dropped** (`polling.py:302`). When the anchor arrives via queue-op, the assistant has already started emitting tool_use events (sending the `ask`s); those assistant chunks are lost, which means even if we later set anchor_seen (e.g., via a fallback scan), `last_assistant_uuid` is stale relative to the turn_duration event — matching still fails unless the scanner is willing to look back at the last assistant message. +3. **Restart/resume does not repair anchor state.** When ccbd restarts and resumes a `session_boundary` attempt, `runtime_state.anchor_seen` is whatever it was persisted as (False in the bad path) and the log reader's `offset` is at EOF; there is no "catch up on anchor / last assistant uuid by re-scanning recent log" step. +4. **There is no health metric for "active attempt age without TURN_BOUNDARY item".** A single `dispatcher_poll_completions` step that finds `active_execution_count>0` but oldest attempt age > threshold should raise a fault / auto-repair. + +## 5. Proposed fix + +Minimum viable patch (upstream-worthy): + +1. **Emit a synthetic user event for `queue-operation` enqueued prompts.** + In `parsing_runtime/structured.py`, add a branch after the `system` check: + ```python + if entry_type == "queue-operation": + op = _optional_text(entry.get("operation")) + text = str(entry.get("content") or "") + if op == "enqueue" and text.strip(): + return _event_record( + role="user", + text=text, + entry_type=entry_type, + subtype=subtype, + uuid=uuid, + parent_uuid=parent_uuid, + stop_reason=None, + entry=entry, + ) + ``` + This carries the prompt through to `handle_user_event`, which sets `anchor_seen=True` when the REQ_ID prefix matches. + +2. **Allow assistant-event ingestion before anchor_seen, but only for uuid bookkeeping.** + Change `polling.py:302-304` so that assistant events are still fed to a reduced `handle_assistant_event_pre_anchor` path that at least tracks `last_assistant_uuid` (and nothing else — no chunk items, no reply_buffer, no early turn boundary emission). This ensures `is_turn_boundary_event`'s parent_uuid check has the right uuid even when the anchor arrives mid-turn after some assistant events already exist. + +3. **Add an attempt-level completion watchdog.** + In the dispatcher's poll loop, for each active attempt older than `CCB_ATTEMPT_TIMEOUT_S` (default e.g. 600 s) with no TURN_BOUNDARY/ERROR/PANE_DEAD item ever produced, force-terminalize it with `status=incomplete, reason=turn_boundary_timeout, confidence=degraded`, and move on to the next queue item. Publish a fault entry and leave enough diagnostics (session_path, last_offset, last_seen_entry_type) to diagnose without re-running. + +4. **Resume-time anchor catch-up.** + When a `session_boundary` attempt is resumed, scan the last N KiB (or last ~200 entries) of the session log backward from the persisted offset to find (a) the anchor marker and (b) the latest assistant uuid, so a missed anchor across ccbd restart does not strand the job. + +5. **Telemetry.** + Emit a counter metric `ccb.completion.anchor_missing_after_seconds` and fault-inject self-test for the queue-op path so this class of bug has regression coverage. + +## 6. Verification plan + +- Add a fixture session log containing a `queue-operation/enqueue` prompt followed by assistant tool_use events and a `turn_duration` system event. Assert the detector yields `decision.terminal=True, status=COMPLETED, reason in {turn_duration, assistant_end_turn}`. +- Unit-test `structured_event()` for `queue-operation/enqueue` → role=user, text=content. +- Fault-injection test: simulate prompt delivery while REPL busy → confirm the watchdog trips within the configured timeout instead of hanging forever. +- Live soak on the `pm` agent in the MiniMES project for ≥4 hours; assert zero attempts stay in `running` > watchdog threshold, and that the 14 historical deadlocked jobs listed in §2.2 would have completed under the patched parser. + +## 7. Workaround for users until the fix ships + +- `ccb restart pm` (or the stuck claude agent) unblocks the queue but loses in-flight agent context. +- `ccb repair` can in some cases advance the head event; unreliable for this specific bug because the underlying completion detector never sees the boundary. +- Avoid sending messages to a busy claude agent (wait for its mailbox to go idle before ask); not practical for pm which is the hub. diff --git a/lib/provider_backends/claude/comm_runtime/parsing_runtime/structured.py b/lib/provider_backends/claude/comm_runtime/parsing_runtime/structured.py index d61c27e65..ba8010b82 100644 --- a/lib/provider_backends/claude/comm_runtime/parsing_runtime/structured.py +++ b/lib/provider_backends/claude/comm_runtime/parsing_runtime/structured.py @@ -39,6 +39,29 @@ def structured_event(entry: dict[str, Any]) -> dict[str, Any] | None: entry=entry, ) + # Emit a zero-text assistant event for assistant entries whose content is + # pure tool_use / thinking blocks (no visible text). The completion + # detector ignores these for reply extraction, but the state machine needs + # them for `last_assistant_uuid` bookkeeping so that a subsequent + # system/turn_duration event can match its parent_uuid. This case arises + # when the assistant dispatches multiple async CCB asks (pure tool_use + # turns) before emitting its final end_turn text summary. Without this + # bookkeeping, a prompt delivered via `queue-operation` (busy REPL) can + # still miss the turn boundary because the pre-anchor uuid tracker never + # sees intermediate assistant tool_use events (structured_event previously + # returned None for them since extract_message yields no text). + if _is_assistant_tool_use_entry(entry): + return _event_record( + role="assistant", + text="", + entry_type=entry_type, + subtype=subtype, + uuid=uuid, + parent_uuid=parent_uuid, + stop_reason=_assistant_stop_reason(entry), + entry=entry, + ) + if entry_type == "system": return _event_record( role="system", @@ -50,6 +73,34 @@ def structured_event(entry: dict[str, Any]) -> dict[str, Any] | None: stop_reason=None, entry=entry, ) + + # Claude Code CLI queues incoming input when the REPL is busy (cooking / in a + # tool_use turn). In that case the prompt is recorded as a + # `queue-operation`/`enqueue` entry (with the full prompt in `content`) plus + # a later `attachment`/`queued_command` marker. It does NOT synthesize a + # `type:"user"` message entry. If we drop the record the completion + # detector never sees the anchor marker (`CCB_REQ_ID:`) and the attempt + # deadlocks: anchor_seen stays False, assistant events are gated out, + # last_assistant_uuid is never updated, and the `turn_duration` system + # event can never match. Emit a synthetic user event so the rest of the + # pipeline (handle_user_event / anchor detection) works identically to the + # idle-REPL path. See docs/claude-queue-operation-completion-deadlock-diagnosis.md. + if entry_type == "queue-operation": + op = _optional_text(entry.get("operation")) + if op == "enqueue": + text = str(entry.get("content") or "").strip() + if text: + return _event_record( + role="user", + text=text, + entry_type=entry_type, + subtype=subtype, + uuid=uuid, + parent_uuid=parent_uuid, + stop_reason=None, + entry=entry, + ) + return None @@ -60,6 +111,30 @@ def _assistant_stop_reason(entry: dict[str, Any]) -> str | None: return _optional_text(message.get("stop_reason"), lowercase=False) +def _is_assistant_tool_use_entry(entry: dict[str, Any]) -> bool: + if str(entry.get("type") or "").strip().lower() != "assistant": + return False + message = entry.get("message") + if not isinstance(message, dict): + return False + if str(message.get("role") or "").strip().lower() != "assistant": + return False + content = message.get("content") + if not isinstance(content, list) or not content: + return False + for item in content: + if not isinstance(item, dict): + return False + ctype = str(item.get("type") or "").strip().lower() + if ctype in {"text", "tool_result"}: + # Has real visible text → extract_message would have caught it. + return False + if ctype in {"tool_use", "thinking", "thinking_delta"}: + continue + return False + return True + + def _event_record( *, role: str, diff --git a/lib/provider_backends/claude/execution_runtime/polling.py b/lib/provider_backends/claude/execution_runtime/polling.py index dcbcd7edb..ba84f89d3 100644 --- a/lib/provider_backends/claude/execution_runtime/polling.py +++ b/lib/provider_backends/claude/execution_runtime/polling.py @@ -299,11 +299,86 @@ def _process_event( return None if role == "system": return handle_system_event(submission, poll, event, now=now, state=state) - if role == "assistant" and poll.anchor_seen: - handle_assistant_event(submission, poll, event, now=now) + if role == "assistant": + # Always bookkeep assistant uuids even before the anchor is seen, so + # that when a turn_duration system event arrives later its + # parent_uuid match does not short-circuit on an empty + # last_assistant_uuid. Without this, a prompt that landed as a + # Claude-CLI `queue-operation` record (busy REPL) — even after the + # structured_event fix — would still fail to match turn_duration + # because assistant tool_use chunks before anchor_seen were skipped + # entirely. Full event handling (chunks/reply_buffer/turn boundary + # emission) still requires anchor_seen. + _bookkeep_assistant_uuid_pre_anchor(poll, event) + if poll.anchor_seen: + handle_assistant_event(submission, poll, event, now=now) return None +def _bookkeep_assistant_uuid_pre_anchor(poll, event: dict) -> None: + """Track the latest assistant uuid even before the anchor is seen, so that + `is_turn_boundary_event` can match a subsequent system/turn_duration + event's parent_uuid against it. Without this, an assistant turn composed + entirely of tool_use chunks (no text reply yet, as in pm dispatching + parallel asks) leaves last_assistant_uuid empty; when the final + end_turn/turn_duration finally arrives, parent_uuid check in + event_reading/turns.py fails the `if not last_assistant_uuid: return False` + guard and the turn boundary is missed. We read from the raw entry + (event["entry"]) so that tool_use-only assistant events (which produce no + extract_message text and are therefore elided by structured_event) are + still observed. + See docs/claude-queue-operation-completion-deadlock-diagnosis.md. + """ + if poll.anchor_seen or poll.reached_turn_boundary: + return + entry = event.get("entry") if isinstance(event, dict) else None + if not isinstance(entry, dict): + # Fallback: structured event may carry a top-level uuid. + euid = str(event.get("uuid") or "").strip() + if euid: + poll.last_assistant_uuid = euid + return + entry_type = str(entry.get("type") or "").strip().lower() + if entry_type != "assistant": + return + msg = entry.get("message") + if not isinstance(msg, dict): + return + if str(msg.get("role") or "").strip().lower() != "assistant": + return + # Skip subagent/session child entries conservatively; top-level assistant + # tool_use for bash/ask is not a subagent. + content = msg.get("content") + if isinstance(content, list): + all_subagent = bool(content) + for item in content: + if not isinstance(item, dict): + all_subagent = False + break + if item.get("type") != "tool_use": + all_subagent = False + break + inp = item.get("input") if isinstance(item.get("input"), dict) else {} + nm = str(item.get("name") or "").lower() + if nm in {"task", "subagent", "spawn_subagent"}: + continue + sub_name = str(inp.get("subagent_name") or inp.get("agent_name") or "").strip() + if not sub_name: + all_subagent = False + break + if all_subagent: + return + euid = str(entry.get("uuid") or "").strip() + if euid: + poll.last_assistant_uuid = euid + + +def _event_is_subagent(entry: object) -> bool: + # Retained for backwards compatibility; replaced by inline logic in + # _bookkeep_assistant_uuid_pre_anchor. + return False + + __all__ = [ "is_turn_boundary_event", "poll_exact_hook",