Skip to content

fix(spawn): checkpoint sub-session transcripts during the run so a timed-out delegate is resumable - #291

Merged
Brian Krabach (bkrabach) merged 4 commits into
mainfrom
lane/3yc-timedout-session-not-resumable
Sep 2, 2026
Merged

fix(spawn): checkpoint sub-session transcripts during the run so a timed-out delegate is resumable#291
Brian Krabach (bkrabach) merged 4 commits into
mainfrom
lane/3yc-timedout-session-not-resumable

Conversation

@bkrabach

@bkrabach Brian Krabach (bkrabach) commented Sep 2, 2026

Copy link
Copy Markdown
Collaborator

DONE-NOTE — model_performance-3yc

A timed-out sub-session is never persisted, so the session_id in its result is not resumable

Lane spend: $0.00 — code reading + local pytest only. No API calls, no DTU, no infrastructure
created (nothing to register in the infra ledger, nothing to tear down).
Repo: amplifier-app-cli · branch lane/3yc-timedout-session-not-resumable · base 963d793
Claim tags: (knob) · (family) · (confidence: measured / inferred / assumed) · (evidence: file:line)


1. VERIFIED MECHANISM (against the current base, not the filing base)

The item was filed against f16375fc. Re-read at 963d793 (current origin/main); the mechanism
is unchanged, only the line numbers moved.

claim evidence at 963d793 confidence
the child transcript is read only after a successful execute() session_spawner.py:845 response = await child_session.execute(instruction):857 transcript = await context.get_messages() measured
store.save runs only after that session_spawner.py:887 store.save(sub_session_id, transcript, metadata) measured
there is no except on the execute block — only finally session_spawner.py:843-910 measured
the same defect exists on the RESUME path (not mentioned in the item) session_spawner.py:1619 execute → :1629 store.save, same try/finally shape measured
the metadata store.save needs is fully known BEFORE execute merged_config :298, agent_config :290/:295, self_delegation_depth (parameter :242), _extract_bundle_context(parent_session) — none depend on the response measured
store.save itself is fully synchronous session_store.py:100-131_save_transcript / _save_metadata / write_with_backup, no await anywhere measured
resume reconstructs purely from metadata["config"] + metadata["agent_overlay"] + transcript session_spawner.py:966-970, :1314-1327, :1556-1559 measured

The last two are the load-bearing findings. Together they mean (a) the persist step needs exactly one
await
context.get_messages() — and (b) everything else it needs is available before the run starts.


2. THE DECISION — option (b), persist during the run

Chosen: (b) persist the transcript incrementally during the run, so no cancellation-path write is
needed at all.
The cancellation path gains no new code, no new await, and no new write.

How this satisfies the hard invariant — "the fix must NOT introduce an unbounded await on the
cancellation path".
The danger is specific: an await reached while a task is unwinding a fired
deadline can block past the very deadline that caused the unwind, re-creating the hang the timeout
exists to bound. Options (a) and (b) differ in where they discharge that risk. (a) puts work on the
cancellation path and then tries to bound it — so the invariant holds only as strongly as the bound,
and §2 shows the bound is partly fictional. (b) moves the work to normal execution, where blocking is
already accepted and the post-run save has always done exactly this work; it changes when the
transcript is written, not what. The invariant then holds by construction rather than by
argument
: there is no new statement on the cancellation path to bound, so there is nothing to get
wrong. §3 proves it empirically anyway — get_messages() is made to hang forever from the instant
cancellation is delivered, and the unwind is unaffected.

Why not (a) — asyncio.shield + a hard secondary timeout

Rejected on a measured, not aesthetic, ground: the bound would be partly fictional.

  1. store.save() is synchronous (session_store.py:100-131). asyncio.wait_for can only
    interrupt at an await. It therefore cannot bound the disk write — the part most likely to be
    slow on a loaded or networked filesystem. The "hard secondary timeout" would bound
    get_messages() and nothing else, while reading as though it bounded the save.
  2. Once a deadline's CancelledError has been delivered and caught, a fresh await is not
    re-cancelled
    — it simply blocks. This is demonstrated directly, as executable code, in
    test_the_probe_would_catch_a_violating_implementation: the option-(a) shape hangs past its own
    0.2 s deadline and never unwinds. That is precisely the hang the timeout exists to bound.
    (confidence: measured — the control test hangs deterministically.)
  3. shield + wait_for leaks the shielded task when the outer wait_for fires, and a re-entrant
    parent cancellation (Ctrl-C, an outer timeout) then propagates out of the handler — which
    DESIGN.md §3 establishes would destroy the sibling delegates the timeout path exists to protect.

Why not (c) — mark the result explicitly non-resumable

Legitimate, and it was seriously weighed. Rejected for three reasons, in order of weight:

  1. The value discarded is large and known. Measured delegate legs run 284–1543 s ([SOL], via
    00 §2c); sol S1 runs cost $15.96–$27.18 median/run (00 §2c). Option (c) makes every timeout
    throw away the whole transcript and forces the caller to pay for it again from zero. Option (b)
    costs a handful of small synchronous writes per run.
  2. It does not compose with 37n. model_performance-37n already preserves the in-flight
    assistant text via the session.partial capability. What is still missing is the completed
    turns
    , which is exactly what makes "resume where it left off" work. (b) supplies the missing
    half; (c) declares the gap permanent.
  3. Its deliverable is not in this repo. The result shape (partial_available, guidance,
    status) lives in amplifier-foundation's tool-delegate, outside this lane's owned repo. A
    resumable: false flag shipped here could not be surfaced by the consumer without a second,
    coordinated PR. (This is a practical constraint, not the reason — reasons 1 and 2 stand alone.)

Honest note: (c) is still the correct labelling answer for the residual gap. The subprocess
spawn path (session_spawner.py:637) returns before any checkpointing and remains unresumable on
timeout — see §5.

The design, and why provider:request

  • The transcript is checkpointed during normal execution, where blocking is already accepted
    (the post-run save has always done exactly this work — this moves when, not what).

  • One checkpoint is written before execute() (pre-registration), so the advertised session_id
    resolves in SessionStore even if the timeout fires during the very first LLM call.

  • Mid-run checkpoints fire on provider:request — emitted at
    loop_streaming/__init__.py:3202 (per iteration) and :2996 (turn start).
    (confidence: measured — code read at cache amplifier-module-loop-streaming-b0b975ea6a1072dd.)

    provider:request is not an arbitrary choice: it is the only point in the loop where the message
    list is guaranteed tool-pair-balanced.
    The previous round's tool results have all been appended,
    and the next assistant message (which may open new tool_calls) does not exist yet. Checkpointing
    on provider:response would persist an assistant message with unmatched tool_calls, and resuming
    that transcript reproduces the InvalidRequestError: No tool call found for function call output
    class of failure recorded for context-managed in 00 §2g (29 of 30 turns).
    (confidence: inferred — the balance property is read from the loop; the resulting provider error
    is measured, but in the cited context-managed runs, not here.)

  • Checkpoints are labelled status: "in_progress"; only the post-run save writes status: "complete".
    A caller can therefore tell a rescued checkpoint from a finished session.

  • Applied to both spawn_sub_session and resume_sub_session — the resume path had the same
    defect and the item did not mention it.

The knob

AMPLIFIER_SPAWN_CHECKPOINT_INTERVAL_S, default 30.0 s. CHOSEN, NOT MEASURED, and labelled as
such in the source comment.
No data exists on sub-session checkpoint sizes because no mid-run
checkpoint has ever been written, so there is nothing to bank (00 §5 rules 3 and 6). The reasoning
recorded in-source: 30 s bounds the transcript lost to a timeout to at most one window against legs
of 284–1543 s, while capping write amplification on fast-iterating sub-sessions. A negative value
disables checkpointing entirely and restores the pre-fix behaviour exactly — pinned by a test.


3. THE HARD INVARIANT, AND HOW IT IS PROVED

The fix must NOT introduce an unbounded await on the cancellation path.

Proved by TestNoUnboundedAwaitOnCancellationPath — two assertions plus a control:

  1. test_hanging_get_messages_does_not_delay_the_unwindcontext.get_messages() is made to
    hang forever from the instant cancellation is delivered. The spawn runs under a 0.2 s
    asyncio.timeout, exactly as tool-delegate:1092 does. Asserts: the unwind completes (the
    harness fails loudly at 5 s rather than hanging the suite), elapsed < 2 s, and
    get_messages's call count did not move after cancellation began. The count assertion is what
    stops the test passing by accident.

  2. test_the_probe_would_catch_a_violating_implementation — the inverted control, present
    because of 00 §5 rule 5. This is a gate that would otherwise be vacuous: the unpatched code
    ALSO has no await on its cancellation path, so assertion 1 passes before the fix as well
    (verified — see §4). It is a regression guard, not a defect reproduction, and a guard is worth
    nothing unless it can fail. The control reproduces the rejected option-(a) shape and asserts the
    probe's instrument does catch it. Disclosed rather than presented as a pass.

  3. test_cleanup_still_runs_and_the_timeout_still_propagates — the timeout still surfaces as
    TimeoutError, child_session.cleanup() still runs, unregister_child still runs, and the
    checkpoint hook is unregistered even on the timeout path.

The contract the acceptance names — BOTH branches are tested

The acceptance is disjunctive: "either the advertised session_id is genuinely resumable … or the
result states explicitly that it is not resumable and directs the caller to re-delegate."
Option (b)
resolves it to the first branch for every checkpointed session. Two residual cases are not
checkpointed and land on the second. Both branches are covered.

Branch 1 — TestTimedOutSessionIsResumable:

  • test_timed_out_spawn_leaves_a_loadable_session — after a real 0.2 s timeout, SessionStore holds
    the session, the transcript is the preserved messages, status == "in_progress", and
    metadata["config"] is present.
  • test_timed_out_session_round_trips_through_resume — the full recovery move, end to end: spawn
    → time out → call the real resume_sub_session(session_id) → assert the preserved transcript is
    restored into the resumed session's context.

Branch 2 — TestNonResumableIsStatedExplicitly:

Residual non-checkpointed cases: the subprocess spawn path (session_spawner.py:637 returns
before any checkpointing), checkpointing explicitly disabled via the env knob, plus the
pre-existing expired/pruned/never-existed cases. resume_sub_session now raises a message that
states non-resumability in words and names the correct move, rather than leaving "retry the
resume" as a plausible reading:

Sub-session '<id>' not found. Session may have expired or was never created. This session is NOT resumable -- re-delegate to start a fresh session instead of retrying the resume.

  • test_missing_session_says_not_resumable_and_says_re_delegate — asserts both "not resumable" and
    "re-delegate" are present.
  • test_disabled_checkpointing_lands_on_the_non_resumable_branch — the disjunction resolving the
    other way in a real run: spawn → time out with checkpointing off → the id is genuinely absent
    and asking to resume it says so explicitly.

BRANCH 2 SPANS TWO REPOS, AND BOTH HALVES ARE NOW DONE — the second ships as a verified patch.
Verified at file:line, not assumed: tool-delegate's handler
(modules/tool-delegate/amplifier_module_tool_delegate/__init__.py:1314-1332 @ cc7e23a) catches
FileNotFoundError, uses str(e) only in the delegate:error event, and returns a hardcoded
message that discards it — so the app-side wording reached the event, the logs and non-foundation
callers, but not the ToolResult the model reads.

PATCH-foundation-surface-resume-detail.diff (in this directory) closes it:

"message": str(e)
or f"Agent session '{session_id}' not found. May have expired or never existed."

Detail-preserving, with the original sentence retained as the empty-detail fallback.

check result
git apply --check @ cc7e23a exit 0
tool-delegate suite, UNPATCHED baseline 48 passed
tool-delegate suite, PATCHED (scratch copy) 48 passed
foundation working tree afterwards clean — the repo was never modified

The round trip is proved, not asserted in halves.
test_resume_message_roundtrip.py (beside the patch) wires the real app-side
resume_sub_session into the real tool-delegate resume path and reads the resulting ToolResult:

  • against PATCHED tool-delegate: 2 passed;
  • against UNPATCHED: 1 failed, 1 passed, and the failure prints the exact string the model
    would otherwise see — "Agent session '<id>' not found. May have expired or never existed."

That asymmetry is the result: it is what makes the foundation diff necessary rather than cosmetic.
The file lives beside the patch, not in tests/, because it depends on an unlanded change and
would otherwise redden CI — the same convention the w3/37n lane used for test_partial_roundtrip.py.

Landing order: this app-cli PR is safe alone (the wording still reaches the event, the logs and
non-foundation callers). Land the foundation diff to complete the model-facing half.

Deliberately not worked around from this side: the only in-repo lever would be raising a
different exception type so foundation's generic except Exception (:1312, which does pass
str(e) through) caught it instead — trading away a structured, correctly-typed error branch to
smuggle a string. That is a worse design and it is not done.


4. VERIFICATION

check result
full suite, baseline at 963d793 before any change 1560 passed, 1 skipped, 13 deselected, 1 xfailed
full suite, patched (-p no:randomly) 1573 passed, 1 skipped, 13 deselected, 1 xfailed
full suite, patched (default random order) 1573 passed, 1 skipped, 13 deselected, 1 xfailed
new test file alone 13 passed
new test file against the UNPATCHED spawner (falsifier check) 10 failed, 3 passed
ruff check / ruff format --check on every file this PR touches clean

The falsifier check matters, and its three passes are disclosed, not hidden. Reverting only
session_spawner.py to 963d793 and re-running the new file gives 10 failed, 3 passed. The three
that still pass, and why each is correct rather than vacuous:

test why it passes pre-fix
test_hanging_get_messages_does_not_delay_the_unwind the unpatched cancellation path is also await-free — this is a regression guard, not a defect reproduction (see §3.2)
test_the_probe_would_catch_a_violating_implementation it is a self-contained control over a synthetic option-(a) coroutine; it never touches the spawner
test_negative_interval_disables_checkpointing_entirely it pins that the escape hatch reproduces exactly the pre-fix behaviour

None is claimed as a defect reproduction.

One existing test was modified, and the reason is not "to make the new code pass": FakeHooks in
tests/test_session_spawner.py (two copies) modelled the hook registry as a single handler slot,
ignoring the event name
. The real registry is event-keyed. Registering a second hook made the last
writer win, hiding the orchestrator:complete handler the test asserts on. The fake now honours the
event name. The test's intent and assertions are untouched.


5. WHAT THIS DOES NOT CLAIM

  1. No eval was run. $0 lane. Every result above is a local unit test. No live delegate has ever
    timed out under this patch.
  2. The 30 s default is chosen, not measured (00 §5 rule 6). It is labelled as such in the source.
  3. Write amplification is not measured. _save_transcript rewrites the whole JSONL per
    checkpoint, so cost is O(checkpoints × transcript size), bounded by the throttle. No workload
    measurement exists. store.save is synchronous, so each checkpoint briefly blocks the event loop
    — the same operation the post-run save has always performed, now up to N times per run.
  4. The subprocess spawn path is still not CHECKPOINTEDsession_spawner.py:637 returns before
    any checkpointing, so a subprocess-mode delegate that times out cannot be resumed. It is now
    covered by the acceptance's second branch instead (it says so explicitly and directs a
    re-delegate, §3), but the model-facing half of that message needs the one-line foundation change
    specified in §3. Making the subprocess path itself checkpointable is a separate piece of work and
    is NOT attempted here.
  5. Up to one throttle window of transcript can still be lost. Because the transcript only changes
    between provider calls, the practical loss is "iterations that completed within the last 30 s",
    not 30 s of work — but that is reasoned, not measured.
  6. The tool-pair-balance argument for provider:request is inferred from reading the loop. The
    consequence of getting it wrong is measured, but in 00 §2g's context-managed runs, not here.
  7. This PR does not enable any timeout. settings.timeout remains None by default in
    tool-delegate. Landing order from DESIGN.md §7 is unchanged: foundation, then app-cli, then
    sweep the timeout.
  8. No Anthropic guardrail run was performed (00 §5 rule 9). This patch changes only local disk
    writes on the app side — it adds no request, alters no prompt, and touches no provider payload, so
    there is no cache surface to regress. That is an argument, not a measurement.

6. FILES

file what
amplifier_app_cli/session_spawner.py _checkpoint_interval_s, _write_checkpoint, _install_transcript_checkpoint; metadata + store construction moved before execute(); checkpoint wired into both the spawn and resume paths; status field on saved metadata; explicit not-resumable/re-delegate wording on the resume-miss error
tests/test_timedout_session_resumable.py 13 new tests — BOTH branches of the disjunctive contract, the invariant, the inverted control, the boundary choice, best-effort behaviour, the throttle and the escape hatch
tests/test_session_spawner.py FakeHooks made event-keyed (see §4)
ai_working/3yc-timedout-session-resumable/DONE-NOTE.md this note
ai_working/3yc-timedout-session-resumable/PATCH-foundation-surface-resume-detail.diff the foundation half of branch 2; git apply --check exit 0 @ cc7e23a, 48 passed patched and unpatched
ai_working/3yc-timedout-session-resumable/test_resume_message_roundtrip.py cross-repo round trip: 2 passed patched, 1 failed unpatched (deliberately outside tests/)

…med-out delegate is resumable

store.save() ran only after a successful `await child_session.execute(...)`.
tool-delegate's wall-clock timeout CANCELS that await, so the save never ran and
nothing about the timed-out sub-session reached SessionStore -- the session_id
handed back to the caller could not be resumed ("Session not found. May have
expired or never existed."). The resume path had the identical defect.

Rescuing the transcript from the CANCELLATION path would mean awaiting
context.get_messages() while already unwinding a deadline -- an await that can
block past the very deadline that caused the unwind. store.save() is also
synchronous, so an asyncio.wait_for around it could not interrupt the disk write
at all. So the cancellation path is left entirely untouched: no new code, no new
await, no new write.

Instead the transcript is checkpointed during NORMAL execution:
  - once before execute() (pre-registration), so the advertised session_id
    resolves even if the timeout fires during the first LLM call;
  - then on provider:request, throttled by
    AMPLIFIER_SPAWN_CHECKPOINT_INTERVAL_S (default 30s, chosen not measured;
    negative disables).

provider:request is the only point in the orchestrator loop where the message
list is guaranteed tool-pair-balanced -- checkpointing after a response would
persist an assistant message with unmatched tool_calls, and resuming that
reproduces "No tool call found for function call output".

Checkpoints are labelled status="in_progress"; only the post-run save writes
status="complete", so a caller can tell a rescued checkpoint from a finished
session.

Tests (11 new) pin: the end-to-end resume round trip; that nothing is awaited on
the cancellation path (a hanging get_messages does not delay the unwind, plus an
inverted control proving that probe can fail); the provider:request boundary
choice; best-effort behaviour when a checkpoint or the hook registry fails; and
the throttle and disable escape hatch.

tests/test_session_spawner.py: FakeHooks modelled the hook registry as a single
handler slot ignoring the event name; the real registry is event-keyed. Made it
honour the event so a second registration no longer hides the first.

Refs: model_performance-3yc (follow-up to model_performance-37n, DESIGN.md 3)
…stated explicitly

The acceptance contract is disjunctive: either the advertised session_id
genuinely resumes, or the result states explicitly that it is not resumable and
directs the caller to re-delegate. Option (b) resolves it to the first branch for
every checkpointed session. Two residual cases are not checkpointed and land on
the second: the subprocess spawn path (session_spawner.py:637 returns before any
checkpointing) and checkpointing disabled via the env knob — plus the
pre-existing expired / never-existed cases.

resume_sub_session's not-found error now says so in words and names the correct
move, instead of leaving "retry the resume" as a plausible reading:

  "... This session is NOT resumable -- re-delegate to start a fresh session
   instead of retrying the resume."

Two new tests pin it, including an end-to-end run where the disjunction resolves
the OTHER way: spawn -> time out with checkpointing off -> the id is genuinely
absent AND asking to resume it says so explicitly.

SCOPE, verified at file:line rather than assumed: tool-delegate's
`except FileNotFoundError` handler (foundation
modules/tool-delegate/.../__init__.py:2148-2166) uses str(e) only in the
delegate:error event and returns a HARDCODED result message that discards it. So
this text reaches the event, the logs, and every non-foundation caller, but not
the model-facing ToolResult. Closing that half is a one-line foundation change
(error={"message": str(e)}), specified in the PR body. Deliberately not worked
around by raising a different exception type to hit foundation's generic
handler — that trades a correctly-typed error branch for a string.

13 tests in the file (was 11); suite 1573 green (was 1571).

Refs: model_performance-3yc
…ch + cross-repo round trip

The acceptance's second branch requires the result to state explicitly that a
session is NOT resumable and direct the caller to re-delegate. The previous
commit made amplifier-app-cli raise exactly that -- but verification at
file:line showed tool-delegate's `except FileNotFoundError` handler
(foundation modules/tool-delegate/.../__init__.py:1314-1332 @ cc7e23a) uses
str(e) only in the delegate:error event and returns a HARDCODED message that
discards it. So the wording reached the event, the logs and non-foundation
callers, but NOT the ToolResult the model reads. Branch 2 was therefore
incomplete in the system the model actually sees.

Adds:
  PATCH-foundation-surface-resume-detail.diff
      "message": str(e) or <original sentence>       # detail-preserving,
      original retained as the empty-detail fallback
      git apply --check @ cc7e23a: exit 0
      tool-delegate suite: 48 passed unpatched, 48 passed patched (scratch
      copy; the foundation repo was never modified -- verified clean after)

  test_resume_message_roundtrip.py
      Wires the REAL app-side resume_sub_session into the REAL tool-delegate
      resume path and reads the resulting ToolResult.
      PATCHED:   2 passed
      UNPATCHED: 1 failed, 1 passed -- the failure prints the exact string the
                 model would otherwise see. That asymmetry is the result; it
                 is what makes the diff necessary rather than cosmetic.

Both live in ai_working/, NOT tests/, because the round trip depends on an
unlanded foundation change and would otherwise redden CI -- the same convention
the w3/37n lane used for test_partial_roundtrip.py.

Landing order: this app-cli PR is safe alone; land the foundation diff to
complete the model-facing half.

Suite unchanged at 1573 green (ai_working is not collected; testpaths=["tests"]).

Refs: model_performance-3yc
…ded-await invariant

The PR body argued (a) and (c) down but left (b)'s own justification against
the hard invariant implicit. Names the specific danger (an await reached while
unwinding a fired deadline can block past that deadline), and why (b) discharges
it by construction rather than by a bound that has to hold.

Refs: model_performance-3yc
@bkrabach
Brian Krabach (bkrabach) marked this pull request as ready for review September 2, 2026 21:32
@bkrabach
Brian Krabach (bkrabach) merged commit 0d93352 into main Sep 2, 2026
7 of 9 checks passed
@bkrabach
Brian Krabach (bkrabach) deleted the lane/3yc-timedout-session-not-resumable branch September 2, 2026 21:32
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