Skip to content

fix(agent-server): recover a completed turn reported as error_during_execution (#1870) - #1944

Merged
vybe merged 7 commits into
devfrom
trinity-ability/issue-1870
Aug 4, 2026
Merged

fix(agent-server): recover a completed turn reported as error_during_execution (#1870)#1944
vybe merged 7 commits into
devfrom
trinity-ability/issue-1870

Conversation

@trinity-ability

Copy link
Copy Markdown

Fixes #1870

Claude Code can report is_error: true / subtype: error_during_execution for a turn that actually finished. The reproduction is a fan-out turn: the model reaches stop_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_result treated 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).


⚠️ READ FIRST — bounds, rollout, and what was NOT verified

1. Permanent coverage bound: agents with execution_timeout_seconds <= 600 are NOT fixed

The fix reads the session JSONL. That file exists only when session persistence is on. headless_executor auto-enables persistence for timeout_seconds > 600 only, and task_execution_service.execute_task never passes persist_session=True. So every schedule or webhook whose agent has execution_timeout_seconds <= 600 writes 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_reason is None in 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 for event=jsonl_persistence_auto_enabled in 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.sh runs 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-local agent-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.id grouping, _recover_completed_turn_from_jsonl, _safe_stop_reason, _RECOVERY_NOTICE, recovered_terminal), compiled to cpython-314 inside the image.

tests/unit is in NO required CI check. The 4 required checks on dev run 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

File Change
docker/base-image/agent_server/services/jsonl_recovery.py new _recover_completed_turn_from_jsonl, _is_main_thread, _is_before, _safe_stop_reason
docker/base-image/agent_server/services/headless_executor.py _try_recover_completed_turn, _RECOVERY_NOTICE, the nested if in the execution_error branch
docker/base-image/agent_server/models.py ExecutionMetadata.recovered_terminal (additive, defaulted)
docs/memory/requirements/scheduling.md new §10.4.3
docs/memory/feature-flows/parallel-headless-execution.md revision-history row + a new section; corrected a stale error-table row
tests/ test_1870_completed_turn_recovery.py (81), 5 new #1673 pins, a committed real captured transcript fixture, registry entry

Why the #678 recovery could not be reused. _recover_response_from_jsonl picks 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 a since parameter 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 requiredmain-thread only (isSidechain/isMeta excluded 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 carry stop_reason == "end_turn"; max_tokens and stop_sequence rejected).

The recovered answer is the marker message's message.id group, 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 one message.id (thinking then text) and both carry end_turn; measured over 1,075 real transcripts, 40.6% of markers are thinking-only. _read_jsonl_records drops 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.txt declares fastapi>=0.115.0a floor, not a pin. A fresh venv therefore resolves whatever FastAPI is latest, and tests/unit/test_1069_voip_call_path_param.py:214 imports get_flat_dependant from fastapi.dependencies.utils, a symbol newer FastAPI dropped:

ImportError: cannot import name 'get_flat_dependant' from 'fastapi.dependencies.utils'

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.txt or 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 with ModuleNotFoundError: 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_NOTICE is 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:

  1. The revision-history row at the top anchor — same anchor fix(agent-server): never surface Claude Code's [ede_diagnostic] header as the error cause (#1849) #1938 uses. Keep both rows, newest first.
  2. The "execution_error" | 503 → 502 table row. This branch corrects it (it has been wrong since bug: agent-server masks error_during_execution as a successful context: fork placeholder — failed session resumes recorded as success, Sessions-tab fallback never fires #1673 gave the case a dedicated 502 branch).

When resolving, do NOT re-gate on the error string#1938 rewrites that text. This branch's gate is on-disk stop_reason, never the error message, precisely so the two are orthogonal.

Code overlap is zero.

7. #1853 collision note

Both this PR and #1853 edit the same execution_error branch. This PR keeps the raise 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_terminal on the metadata + a notice in the response), so a recovered turn is never indistinguishable from a clean one. No new TaskExecutionStatus value was introducedapply_result writes 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.

  1. Teach the backend to read 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_executions has no metadata column. So today the marker dies on the wirerecovered_terminal is agent-side + on-the-wire only. apply_result's success branch is the single chokepoint.
  2. The Option B verification ask. On the instance that filed bug: completed turn discarded on error_during_execution — jsonl_recovery never consulted, response lost despite end_turn in the JSONL #1870: compare the recovered text against what the retry produced for the 2 cases where the retry succeeded, and confirm that agent's execution_timeout_seconds > 600.
  3. Typed ExecutionMetadata.error_subtype instead of string matching on error_type.
  4. The /api/chat path has no execution_error branch at all — the same class of loss is simply unhandled there.
  5. Surface the <= 600s gap in the UI, or reconsider the auto-persist threshold, so operators are not silently uncovered.
  6. 3 pre-existing Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 log sites interpolate session_id raw (same log-forging shape this PR fixed in its own new lines via !r) — left out of scope deliberately.
  7. tests/unit is order-flaky on dev itself — 4 randomized runs on clean origin/dev gave green / 2 errors / 2 failed / green.

10. Release-note DRAFT TEXT (draft only — no docs/releases/<next>.md was created; 0.8.5 is the latest tag)

Fixed — completed turns are no longer discarded when Claude Code mislabels them as failed (#1870).
Claude Code can report error_during_execution for a turn that actually finished (a background subagent's notification landing after stop_reason: end_turn). The agent server now consults the session transcript for positive evidence of completion before discarding the answer, and surfaces the recovered response as a success with a visible recovery notice.
Requires a base-image rebuild (./scripts/deploy/build-base-image.sh) plus a cold agent recreate — a plain restart does not always adopt the new image.
Bound: the recovery reads the session JSONL, which is only written when session persistence is on (auto-enabled above a 600s execution timeout). Agents with execution_timeout_seconds <= 600 are not covered, and there is no fallback — raise the agent's timeout above 600s to opt in.


Testing

python3 -m pytest tests/unit/test_1870_completed_turn_recovery.py tests/unit/test_1673_execution_error_not_success.py -q
→ 97 passed

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

trinity-ability and others added 7 commits August 2, 2026 14:42
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>
@trinity-ability
trinity-ability marked this pull request as ready for review August 3, 2026 08:54
@github-actions

github-actions Bot commented Aug 3, 2026

Copy link
Copy Markdown

⚠️ Nightly unit-suite check skipped — merge conflict against dev.

Resolve by running git merge dev locally and pushing the result. The next nightly run will re-test once the conflict is gone.

@vybe

vybe commented Aug 3, 2026

Copy link
Copy Markdown
Contributor

/validate-pr — not merged, held on your own gate

Ran this in the merge sweep with #1838/#1910/#1954/#1959/#1752/#1955/#1956. Everything mechanical passes: Fixes #1870, no secrets/IPs/env changes, no schema or config surface, no new top-level backend module, requirements §10.4.3 + the parallel-headless flow doc updated, 97 tests with a real captured transcript fixture.

Held because the PR itself says the real gate hasn't run:

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.

That reasoning is right, and it's reinforced by two other things in the body: tests/unit is in none of the four required checks on dev (Analyze (python), Analyze (javascript-typescript), schema-parity, verify-non-root), so the 97 tests gate nothing on merge; and the verify-local agent-exercise and integration stages didn't run on the host. Merging now would land a change whose only real verification is the one that was skipped.

To unblock

  1. Run the §4.4 live-container check and paste the result.
  2. Note the rollout order in the release notes — this is entirely inside trinity-agent-base, so it needs build-base-image.sh plus a cold recreate per agent (a plain restart doesn't reliably adopt the rebuilt image, bug: a rebuilt agent base image is never picked up — no image-drift predicate, so the v0.8.5 "stop/start-with-recreate" upgrade step is a no-op #1809).

Separately worth filing

The coverage bound is a silent one: agents with execution_timeout_seconds <= 600 write no JSONL, so #1870 stays unfixed for them with no signal beyond an absent event=jsonl_persistence_auto_enabled log line. Measuring 179/179 stop_reason: None in-stream to prove there's no fallback is the right way to establish that — but "the fix silently doesn't apply below a timeout threshold nobody sets deliberately" deserves its own issue rather than living only in this PR body.

The fastapi>=0.115.0 floor-not-pin defect you found is also worth its own issue — it's a repo-wide fresh-venv breakage, not part of #1870.

The stale "merge conflict against dev" bot comment above is a false positive from the nightly's missing merge-base — that's exactly what #1952 fixes.

@vybe vybe left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).

@vybe
vybe merged commit f4a2853 into dev Aug 4, 2026
22 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants