fix(agent-server): recover a completed turn reported as error_during_execution (#1870) - #1944
Conversation
The plan's first draft asserted, from the issue's rendered summary table, that both trailing records are string-content. Measured over 1,075 real transcripts that is wrong: `[Request interrupted by user...]` is LIST content (261 list / 2 str), `<task-notification>` is str (999 / 41). This fixture is extracted from a real CC 2.1.220 transcript, not typed. Structure is byte-preserved (every key, every block shape, the real non-message record interleaving); only free-text values that could carry third-party data are replaced. It carries the E1 shape that matters most: the final message is TWO assistant records sharing one message.id -- `thinking` then `text` -- and BOTH carry stop_reason=end_turn. 40.6% of real end_turn markers are thinking-only. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… to None
Red-first. The recovery function is a stub returning None, so behaviour is
byte-for-byte today's: the 502 still fires. 29 of the 69 tests fail, and the
headline reproduction fails with the issue's exact error:
E fastapi.exceptions.HTTPException: 502: Execution error:
[ede_diagnostic] result_type=user last_content_type=n/a stop_reason=null
Landed with the tests so the gate is exercised behaviourally rather than
dying at import:
- models.py recovered_terminal (C1), deliberately separate from
recovered_from_jsonl
- headless_executor.py _RECOVERY_NOTICE (C2) + _try_recover_completed_turn
+ the nested `if` at the execution_error branch. The
raise body is character-identical, re-indented one level.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…_execution Implements _recover_completed_turn_from_jsonl. Three independent gates, all required: main-thread only x turn-scoped x finished. The load-bearing property: the recovered answer is the marker message's message.id GROUP, fail-closed when that group holds no text -- NOT a text window ending at the marker. A thinking-enabled final message is two records sharing one message.id, and BOTH carry stop_reason=end_turn. Measured here over 1,075 real transcripts / 6,663 main-thread markers: 40.6% are thinking-only, and message.id grouping yields text for 6,660 of them. _read_jsonl_records drops the final partial line on an interrupted write -- and #1870 IS the interrupted-tail case -- so a window rule would return the turn's narration WITHOUT the answer as a 200 SUCCESS, stored, never retried. That is strictly worse than the bug being fixed. Grouping is also the right artifact: a normal success stores only result_text, whereas a window stores intermediate narration (measured window/final ratio p90 2.19x, max 79.5x). Other gates: - _is_main_thread (isSidechain/isMeta) on marker selection, the boundary walk AND text collection. A subagent end_turn + its string-content prompt satisfy both the marker and boundary tests; ungated, a crashed main thread returns 200 with a subagent's internal thought. - The LAST qualifying record must ITSELF be end_turn -- stricter than "the last end_turn in scope", so an interrupted-mid-tool thread cannot be rescued by an earlier marker. - Marker timestamp bounded on BOTH ends. Unparseable since_iso fails closed. - since filter applied to collected records on every path (after a 10MB seek the real failure is a wrong boundary, not a missing one). Observability (both directions, per plan §8): a hit logs completed_turn_recovered_from_jsonl; EVERY decline logs completed_turn_recovery_declined with a specific reason. A fail-closed gate that silently stops firing is otherwise indistinguishable from "the bug never happened". 69/69 new tests green; 180 green across the 9 focus files. The #1673 raise is character-identical (re-indented one level) -- verified mechanically. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…open it #1870 added a recovery step inside this branch, so the #1673 pins now depend on "no JSONL on disk" -- which held only because /home/developer/... does not exist on a test host. Make it an asserted precondition via an autouse _JSONL_PROJECTS_DIR fixture instead of an environmental accident (no CI job runs tests/unit in a container, so the premise is true but implicit). Three new negative tests: - JSONL present but no end_turn => still 502. - The shape that would actually re-open #1673: a PRIOR turn's end_turn in the JSONL AND partial stdout in response_parts => still 502. Exercises the staleness guard and the never-recover-from-stdout invariant together. (The first draft of this test covered the safe direction only.) - Recovery is not attempted for rate_limit / max_turns / authentication_failed even with a perfectly recoverable transcript. Nothing pinned that before. 16 passed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
- requirements/scheduling.md: new 10.4.3 after 10.4.2 (precedent: 10.4.1 is a headless_executor error-classification requirement in the same file). States the <=600s coverage bound as its own bolded clause with the "raise the agent's timeout" lever named -- it is permanent and has NO fallback, because stream-json carries no completion signal at all. - feature-flows/parallel-headless-execution.md, per the plan's binding conflict rule with PR #1938: * revision-history row at the top anchor (same anchor #1938 uses -- an unavoidable, trivially-resolved collision: keep both, newest first) * a NEW section placed AFTER the error-classification region rather than editing lines ~350-400, keeping the conflict surface minimal * FIXED the stale `"execution_error" | 503 | falls through...` table row. It has been wrong since #1673 gave the case a dedicated 502 branch and #1938 does not fix it; leaving a doc permanently self-contradicting about one field to dodge one mechanical conflict is the worse trade. - architecture.md deliberately NOT edited: its only mention (JSONL reaping) stays true and no new cross-cutting surface is added. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Scrutiny item S3/E11 asked whether metadata.error_type is really PERSISTED on the recovered 200 row. Traced: it is NOT -- and neither is recovered_terminal. apply_result's success branch cherry-picks exactly six metadata keys (cache_read/cache_creation/input_tokens, context_window, cost_usd, session_id, compact_events) and drops the rest; schedule_executions has no metadata column; the #1083 async callback converges on the same applier. Consequences, now written down rather than left as an assumption: - R8's "error_type is the audit trail" is false at the DB level. - recovered_terminal (C1) is agent-side + on-the-wire only, exactly as the plan's own C1 rationale anticipated ("a new backend can start reading it later without coordination") -- but that means it is not yet an operator- visible record. - The only signals that actually persist onto the execution row are the recovery NOTICE (it rides inside the stored response text) and the agent log line. So C2 is currently the sole persisted operator-facing signal, not a secondary nicety -- material if anyone later proposes reducing it to a footnote. Follow-up (flagged, not filed): teach apply_result's success branch to read recovered_terminal. That branch is the single chokepoint. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…iew) Three review findings on the #1870 branch, all in the new agent-side recovery surface. No behaviour change on the paths measured in the corpus. 1. CRITICAL — the `message.id`-less window fallback re-opened R13. Verified red: a thinking-only marker (the modal shape after a truncated write, 40.6% of real markers) with no `message.id` made the `(boundary, marker]` walk collect the turn's EARLIER narration — answer entirely absent — and return it as a recovered 200 SUCCESS. That is the exact silent partial-deliverable regression the `message.id` rule was written to prevent, live on the one path that would ever run if Claude Code stopped emitting the field. The marker record must now carry text ITSELF before the window is consulted; a multi-record final message still joins in full, since its last record has text. Pinned by two new tests, one of them the red repro. 2. Decline reasons were conflated, which is how a fail-closed gate rots. A marker with an unparseable/absent timestamp reported as `stale_marker` — so a future CLI moving the `timestamp` field would decline EVERY recovery with a reason an operator reads as "working as designed" and never investigates. Reasons are now split by the action they imply: `marker_no_timestamp` / `malformed_message` (format moved), `future_marker` (clock wrong), `stale_marker` / `sub_thread_only` (guard working), and `not_finished` — the expected steady-state decline, previously indistinguishable from "no assistant records at all" — which carries the observed `stop_reason` as a shape-validated token. 3. Log-forging primitive in the new decline lines. `resume_session_id` reaches `ctx.claude_session_uuid` straight from the /task request body, the agent server logs plain text (`logging.basicConfig`), and Vector splits records on newlines. The new lines interpolated it raw; they now use `!r`, matching what `_read_jsonl_records` already does on its own reject path. The three pre-existing #678 sites with the same shape are left alone and flagged. Also records that `_MAX_FUTURE_CLOCK_SKEW_S` compares two clocks that are both the agent container's own, so it is slop against a corrupt timestamp rather than a tuned cross-host skew budget. tests/unit/test_1870_completed_turn_recovery.py 81 passed (was 80 -> +12 cases across 4 new tests); focused suite 197 passed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Resolve by running |
/validate-pr — not merged, held on your own gateRan this in the merge sweep with #1838/#1910/#1954/#1959/#1752/#1955/#1956. Everything mechanical passes: Held because the PR itself says the real gate hasn't run:
That reasoning is right, and it's reinforced by two other things in the body: To unblock
Separately worth filingThe coverage bound is a silent one: agents with The The stale "merge conflict against |
vybe
left a comment
There was a problem hiding this comment.
Validated via /validate-pr — additive, fail-closed recovery; miss path character-identical to today's 502 (pinned by the #1673 tests); 97 named regression tests off a redacted real fixture; full doc traceability (requirements §10.4.3 + feature flow). Merging; RELEASE is conditioned on the PR's own §4.4 live-container acceptance check + base-image rebuild with cold agent recreate (#1809).
Fixes #1870
Claude Code can report
is_error: true/subtype: error_during_executionfor a turn that actually finished. The reproduction is a fan-out turn: the model reachesstop_reason: end_turn, a background subagent's<task-notification>lands after it, the follow-on turn is interrupted, and the CLI's terminal-state check sees a non-terminal last message — so it reports the whole turn as failed ([ede_diagnostic] result_type=user last_content_type=n/a stop_reason=null)._finalize_headless_resulttreated that as terminal and raised HTTP 502, discarding a complete assistant answer that was sitting on disk. Observed 4× in ~30 runs of one schedule.This adds a new, additive recovery surface consulted from inside that branch. On positive on-disk evidence the completed answer is recovered and the turn returns 200 / SUCCESS; on anything else the 502 is unchanged (character-identical, modulo one indent level).
1. Permanent coverage bound: agents with
execution_timeout_seconds <= 600are NOT fixedThe fix reads the session JSONL. That file exists only when session persistence is on.
headless_executorauto-enables persistence fortimeout_seconds > 600only, andtask_execution_service.execute_tasknever passespersist_session=True. So every schedule or webhook whose agent hasexecution_timeout_seconds <= 600writes no JSONL, and #1870 remains unfixed for it — silently.There is no fallback. This was measured, not assumed: the stream-json events carry no completion signal at all —
message.stop_reasonisNonein 179/179 real assistant records, versus 99.96% populated on disk. There is nothing in memory to gate on.The only operator lever is raising the agent's execution timeout above 600s (
PUT /api/agents/{name}/timeout). When diagnosing "the fix isn't firing", check forevent=jsonl_persistence_auto_enabledin the agent's logs first — its absence is the answer, not a gate problem.2. Rollout requirement: base-image rebuild + COLD agent recreate
The change is entirely inside
trinity-agent-base. A running fleet keeps discarding completed turns until./scripts/deploy/build-base-image.shruns and each agent is cold-recreated. A plain restart does not always adopt the rebuilt base image (#1809).3. VERIFICATION GAPS — disclosed, not softened
The
verify-localagent-exercise and integration stages did NOT run on this host. The harness could not mint an admin token against its freshly-wiped DB. This reproduced identically on a sibling branch, so it is a host/harness issue rather than something this change caused — but it means those stages provide no evidence here.The plan's §4.4 live-container acceptance check remains OUTSTANDING and has been promoted to REQUIRED. Write the #1870 tail into a real agent's
~/.claude/projects/-home-developer/and drive finalize against it. Synthetic fixtures plus a rebuilt base image can ship a silent no-op — this is the real gate, and it has not been done.What DID pass: backend build + import-smoke, agent build + import-smoke, boot + health. The built image was content-verified to contain the new code (
message.idgrouping,_recover_completed_turn_from_jsonl,_safe_stop_reason,_RECOVERY_NOTICE,recovered_terminal), compiled tocpython-314inside the image.tests/unitis in NO required CI check. The 4 required checks ondevrun no unit tests, so the 97 tests below gate nothing on merge. The live-container check in §4.4 is the real gate.What changed
docker/base-image/agent_server/services/jsonl_recovery.py_recover_completed_turn_from_jsonl,_is_main_thread,_is_before,_safe_stop_reasondocker/base-image/agent_server/services/headless_executor.py_try_recover_completed_turn,_RECOVERY_NOTICE, the nestedifin theexecution_errorbranchdocker/base-image/agent_server/models.pyExecutionMetadata.recovered_terminal(additive, defaulted)docs/memory/requirements/scheduling.mddocs/memory/feature-flows/parallel-headless-execution.mdtests/test_1870_completed_turn_recovery.py(81), 5 new#1673pins, a committed real captured transcript fixture, registry entryWhy the #678 recovery could not be reused.
_recover_response_from_jsonlpicks its boundary by walking backward from the end of file to the newest string-content user record — and the trailing<task-notification>is one. The boundary lands past the completed answer and the forward scan returns nothing. The notification is inside any plausible time window, so asinceparameter would not have helped either: the boundary rule itself is the defect. #1870 therefore adds a new function; the #678 path is untouched and carries zero regression risk.Three independent gates, all required — main-thread only (
isSidechain/isMetaexcluded from marker selection, the boundary walk and text collection) × turn-scoped (marker timestamp within[task_start_iso, now + 300s], fail-closed on both ends) × finished (the last qualifying assistant record must itself carrystop_reason == "end_turn";max_tokensandstop_sequencerejected).The recovered answer is the marker message's
message.idgroup, fail-closed when that group holds no text — never a text window ending at the marker. A thinking-enabled final message is written as two records sharing onemessage.id(thinkingthentext) and both carryend_turn; measured over 1,075 real transcripts, 40.6% of markers are thinking-only._read_jsonl_recordsdrops the final partial line on an interrupted write — and #1870 is the interrupted-tail case — so a window rule would silently store the turn's narration without the answer as a 200 SUCCESS. Every decline is logged with a reason split by the action it implies, so a fail-closed gate that stops firing is distinguishable from "the bug never happened".4. Repo-level defect found during this run (NOT caused by this PR)
tests/requirements-test.txtdeclaresfastapi>=0.115.0— a floor, not a pin. A fresh venv therefore resolves whatever FastAPI is latest, andtests/unit/test_1069_voip_call_path_param.py:214importsget_flat_dependantfromfastapi.dependencies.utils, a symbol newer FastAPI dropped:This is invisible in CI — base and head are both red, so the diff matrix absorbs it — while breaking every fresh local environment that resolves past the drop.
Honest measurement caveat: on this host (FastAPI 0.136.1, Python 3.14) the symbol is still present and the file passes 4/4. The defect is the unpinned floor and the resulting resolution roulette, not a currently-red test on every machine. Recommend pinning FastAPI in
tests/requirements-test.txtor reworking the import to a version-tolerant form.Separately,
tests/unit/test_1771{a,b,c}_*_properties.py(4 files) fail collection on this host withModuleNotFoundError: No module named 'hypothesis'— also pre-existing and unrelated to this branch; they were excluded from the run below.5. Behaviour note — the recovery notice flows downstream
_RECOVERY_NOTICEis prepended into the stored response, so it flows into{{previous_response}}loop templating and fan-out joins. That is deliberate and pinned by test — a recovered turn must never be indistinguishable from a clean one, and the notice is (see item 9) the only signal that actually persists onto the execution row. But a schedule whose downstream parses structured output will now see a markdown blockquote prepended — only on a turn that would otherwise have been a total loss.6. Doc conflicts with PR #1938 (#1849) are EXPECTED — 2 mechanical, code overlap is ZERO
Both PRs touch
docs/memory/feature-flows/parallel-headless-execution.md:"execution_error" | 503 → 502table row. This branch corrects it (it has been wrong since bug: agent-server masks error_during_execution as a successfulcontext: forkplaceholder — failed session resumes recorded as success, Sessions-tab fallback never fires #1673 gave the case a dedicated 502 branch).Code overlap is zero.
7. #1853 collision note
Both this PR and #1853 edit the same
execution_errorbranch. This PR keeps theraise HTTPException(502, …)character-identical modulo one indent level (verified mechanically), so the hand-resolve is six lines.8. Design decision (user-directed)
Recovered turns return 200 / SUCCESS plus a distinguishing signal (
recovered_terminalon the metadata + a notice in the response), so a recovered turn is never indistinguishable from a clean one. No newTaskExecutionStatusvalue was introduced —apply_resultwrites SUCCESS naturally and the #1083 async callback path inherits the fix with no extra wiring.9. Follow-ups — LISTED, DELIBERATELY NOT FILED
No GitHub issues were created for these. File them if/when they are wanted.
recovered_terminal. Traced, not assumed:apply_result's success branch cherry-picks exactly six metadata keys (cache_read_tokens/cache_creation_tokens/input_tokens,context_window,cost_usd,session_id,compact_events) and drops the rest;schedule_executionshas no metadata column. So today the marker dies on the wire —recovered_terminalis agent-side + on-the-wire only.apply_result's success branch is the single chokepoint.execution_timeout_seconds > 600.ExecutionMetadata.error_subtypeinstead of string matching onerror_type./api/chatpath has noexecution_errorbranch at all — the same class of loss is simply unhandled there.<= 600sgap in the UI, or reconsider the auto-persist threshold, so operators are not silently uncovered.session_idraw (same log-forging shape this PR fixed in its own new lines via!r) — left out of scope deliberately.tests/unitis order-flaky ondevitself — 4 randomized runs on cleanorigin/devgave green / 2 errors / 2 failed / green.10. Release-note DRAFT TEXT (draft only — no
docs/releases/<next>.mdwas created; 0.8.5 is the latest tag)Testing
Driven off a committed real captured CC 2.1.220 transcript tail (
tests/unit/fixtures/, redacted — structure byte-preserved, free-text values substituted), not a typed fixture: the plan's first draft asserted from the issue's rendered table that both trailing records were string-content, and measurement over 1,075 real transcripts showed[Request interrupted by user…]is list content (261 list / 2 str).🤖 Generated with Claude Code