fix(execution): SUB-003 post-switch retry gets the turn's remaining budget, not the 300s reader-race ceiling (#2789)

[dolho]

Summary

A 3600s agent took a 429 ~30s into a Workspace turn, SUB-003 moved it to a healthy subscription, and the retry — a full re-run of the user's turn — was dispatched with timeout_seconds=300. The agent server killed its own process group at exactly 300s with stop_reason=tool_use (actively working); the turn was discarded after being billed. Re-sending the same message succeeded.

Both inline retries read _AUTO_RETRY_MAX_TIMEOUT_S. That constant was written for #678's reader-race retry — a re-dispatch of a turn that never started, where "reader races fire fast; 5 min is plenty" is right. The SUB-003 retry (#792/#2638) re-runs the user's whole turn and earns the budget the turn was given. remaining_s already bounds first attempt + retry at the operator's own execution_timeout_seconds, so the second ceiling constrained nothing that wasn't already constrained and cost every turn honestly longer than five minutes. (The issue's alternative min(remaining, max(300, timeout)) is provably a no-op across the PUT-validated 60–7200 range — so the simple form is equivalent and one number fewer.)

Changes

services/task_execution_service.py

• SUB-003 retry: min(remaining_s, 300) → remaining_s. The Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 path keeps its ceiling; the constant's docstring now names which path owns it and why client_portal.portal_attempt_ceiling_seconds (which imports it) depends on that split.
• _AGENT_HTTP_SLACK_S = 10: the first dispatch gives the backend HTTP read 10s more than the agent's own budget so the agent's structured 504 beats a bare ReadTimeout. The retry collapsed both onto one instant — masked by the 300s clamp; with the clamp gone they'd land together. Preserved on the retry.
• _AttemptState.applied_timeout_seconds → _handle_timeout: state.start_time is reset before an inline retry, so _handle_timeout measures the retry — it now judges it against the retry's own budget. A retry that ran its full allowance was labelled bug: abnormal task terminations are labelled Task execution timed out after N seconds when the run never approached N #2106 NETWORK ("aborted after 300s of 3600 seconds allowed"), sending operators to raise a limit that was never reached. The issue's "Compounding" paragraph. None on the first attempt, so test_2106 is untouched. Set inside the Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 CB gate's else — a retry the breaker refuses never runs, and a budget claimed for it would misattribute the original response's terminal.
• _warn_if_retry_budget_clamped: the applied budget appeared in no log line (the report had to reverse-engineer it from "300s of 3600"). Stated at WARNING where decided; silent when nothing was taken.

client_portal/service.py — docstring only: portal_attempt_ceiling_seconds already claimed "unlike the SUB-003 retry, which is capped to the remaining budget". Now true by construction; the note says so and what breaks if the two retries ever share a ceiling again. No marker-TTL change.

Tests

• test_792_subscription_retry.py::test_retry_timeout_bounded — had to change: it asserted ≤ _AUTO_RETRY_MAX_TIMEOUT_S while running at timeout_seconds=300, where the ceiling and the remaining budget are the same number. It passed at every commit and could not have failed for any value of this bug. Re-anchored to the bound that is load-bearing.
• test_2789_subswitch_retry_budget.py (12 new) — 3600s agent gets ~3600s not 300; bounded by the configured cap across 60–7200; HTTP slack preserved on the retry; Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 keeps its ceiling (negative control); portal ceiling still covers one worst attempt; attribution end-to-end (reader-race 502 → retry ReadTimeout on a 3600s turn names "300 seconds allowed", not 3600); clamp WARNING fires/stays quiet correctly.
• Mutation-checked (restore from scratch copy): reverting the budget fix fails 2; mutating the attribution wiring fails the end-to-end one.

Docs — architecture/backend.md bullet, feature-flows/task-execution-service.md SUB-003 section, learnings.md (a constant reused by a second caller carries its first caller's reasoning; a bound-check parameterised at the coincidence certifies whichever bound is wrong).

Accepted residual

A retry whose first attempt already burned most of the budget still gets whatever is left (max(1, …)), and a near-zero retry is billed. Skip-if-hopeless is a separate decision that belongs with #2638.

Test Plan

• cd tests && pytest unit/test_2789_subswitch_retry_budget.py unit/test_792_subscription_retry.py unit/test_2106_timeout_attribution.py unit/test_2133_bounded_reply_poll.py -v — 46 passed
• Full tests/unit/ locally: 16162 passed / 25 failed — 15 are the ::ffff: IPv4-mapped family (local Python 3.12 vs the pinned 3.13), 10 are all of test_792_* failing under full-suite ordering via a leaked pre-dispatch-switch stub (#2638 pre-dispatch switch … before the first attempt in the captured log) — they pass in isolation and when run after this PR's own file. A/B against origin/dev running; CI's base/head diff is the authority.
• Manual: agent with execution_timeout_seconds=3600 on an exhausted subscription + one healthy alternate, send a >5-min tool-heavy turn — expect SUB-003 switched … auto-retry 1/1 and the retry to run past 300s.

Fixes #2789

🤖 Generated with Claude Code

https://claude.ai/code/session_01VpvcfgWkmQPD7DrDLmATTf

[dolho]

/review — head 68dee5fa vs origin/dev (a7acc3dd) — second pass, fresh eyes

Files: 7 (+540/−19) · Scope: CLEAN — the SUB-003 budget, the slack constant, the applied-budget attribution, the clamp warning; one re-anchored test, one new test file, three docs.
Plan completion: every item of the approved plan is DONE with a file:line, and the two review findings I raised on my own first pass (budget claimed above the CB gate; or treating a 0 budget as unset) were fixed before commit.

Critical

None.

Informational

[I1] The clamp WARNING fires on every SUB-003 retry, and calls elapsed time a ceiling (Confidence 8/10)
task_execution_service.py — _warn_if_retry_budget_clamped(agent, "subscription-switch", retry_agent_timeout, timeout_seconds) warns whenever applied < original. On the SUB-003 path that is always true now: retry_agent_timeout = min(timeout, remaining − slack) and remaining < effective_timeout by however long the first attempt ran, so a 3600s agent that took a 429 at 30s logs "retry budget clamped to 3570s of the turn's 3600s — a timeout at that point is this ceiling, not the configured limit". There is no ceiling; the 30s is the first attempt. The wording is wrong for the common case and the line is noise on every switch. The #678 path's use is right (a real ceiling).
Fix: pass the cause. On the SUB-003 path log at INFO with the breakdown ("retry budget Ns: the turn's Ms less Es already spent") and reserve WARNING for the case that is actually worth a look — the retry has less than _AUTO_RETRY_MAX_TIMEOUT_S left, i.e. the first attempt ate the budget and the re-run is likely hopeless. I'll push this.

[I2] _AGENT_HTTP_SLACK_S is a float; retry_http_timeout - _AGENT_HTTP_SLACK_S when remaining ≤ 10s (Confidence 4/10)
max(1, int(min(timeout, remaining − 10.0))) → agent gets 1s while the backend waits remaining (≤10s). Bounded and honest (the same max(1, …) shape as before), but a 1-second re-run is a billed subprocess that cannot succeed — the "accepted residual" in the PR body. Not changing here; it belongs with the skip-if-hopeless decision on #2638, and I1's WARNING is what makes it visible meanwhile.

Clean

• remaining_s is the only bound and it is sufficient: effective_timeout = timeout + slack, so first attempt + retry ≤ operator cap. Pinned across 60–7200 by test_retry_never_exceeds_the_operators_configured_cap.
• Portal marker derivation unchanged and still true: portal_attempt_ceiling_seconds adds the Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 ceiling once; the SUB-003 retry is remaining-bounded, which its docstring already claimed (test_portal_attempt_ceiling_still_covers_one_worst_attempt).
• Attribution executes end-to-end: test_terminal_reports_the_retrys_limit_end_to_end drives reader-race 502 → ReadTimeout on a 3600s turn and asserts the terminal names 300s; mutating _handle_timeout's limit read turns it red.
• applied_timeout_seconds is set only inside the CB gate's else on the Async chat_with_agent: long execution silently fails with null response (reader-thread) #678 path, so a refused retry claims no budget.
• No auth/credential surface; the new log lines carry agent_name and integers only — the CodeQL taint rule about interpolating the destination subscription is preserved.
• Full unit suite A/B: 25 local failures, 15 the Python-3.12 ::ffff: family, 10 all of test_792_* under full-suite ordering only (a leaked #2638 pre-dispatch switch stub from an earlier file; green in isolation and after this PR's own file). Baseline run on plain dev in progress; CI's base/head diff is authoritative.

Verdict: READY after I1 — a log-wording fix, pushing now.

[vybe]

merge-train: not on this train — one critical

The core one-retry fix is right, genuinely executed by tests (I confirmed by mutation: reverting it turns test_post_switch_retry_gets_the_agents_own_timeout_not_300s and test_terminal_reports_the_retrys_limit_end_to_end red), and the #2645 class does not apply here — classify_switch_failure maps 429 → rate_limit, the harness feeds a real _resp_429(), and there's no written-but-inert half. The re-anchoring of test_792::test_retry_timeout_bounded is a legitimate fix to a test that couldn't fail.

❌ Removing the second ceiling breaks the wall-clock bound the PR claims to preserve

task_execution_service.py:2085-2086. The justification at :2069-2075 is that remaining_s is already a hard wall-clock bound, "so first attempt + retry can never exceed what TIMEOUT-001 already promises". That's false on the #678→#792 interplay path, for the reason this same diff documents 200 lines later: state.start_time is reset before the reader-race retry at :1989. When both inline retries fire in one call (502 → reader-race retry → 429 → SUB-003), elapsed_s measures only the reader-race retry, not the turn, and remaining_s re-grants nearly the whole budget a third time.

Measured against a controlled clock (attempt 1 = 3000s, reader-race retry = 5s, timeout_seconds=3600):

	attempt 1	reader-race retry	SUB-003 retry	worst wall-clock
pre-PR min(remaining, 300)	t=0, 3610s	t=3000, 300s	t=3005, 300s	3305s — bound holds
post-PR	t=0, 3610s	t=3000, 300s	t=3005, 3605s	6610s — broken

One execute_task can now hold its capacity slot for 1h50m on a turn budgeted at 3600s — 83% over execution_timeout_seconds and 2700s past portal_attempt_ceiling_seconds(3600) = 3910. Three pieces of existing machinery are sized on the old bound:

• portal_attempt_ceiling_seconds (client_portal/service.py:3261) under-counts by roughly a whole turn — the exact failure its own docstring warns about, and this PR edits that docstring at :3250-3253 to assert the derivation is now "true by construction".
• Slot lease expires mid-run: slot_service.py:126 TTL = timeout_seconds + 300 = 3900s < 6610s.
• Watchdog terminates mid-run: cleanup_service.py:2220-2243 fires at age_seconds > timeout_seconds, and the retry reuses the same execution_id without re-stamping started_at — so at t≈3600 it kills a run the backend is still awaiting. That's the contradictory-terminal class Invariant Feature/gemini runtime support #2 / bug: recovery paths write execution terminals without closing the paired activity — agent shows as running for up to 2h, then logs a fabricated 120-min failure #1804 exists to prevent.

The repo already has a named test for this path: tests/unit/test_792_subscription_retry.py::test_678_interplay_both_retries_fire.

Fix shape: carry a turn-level clock that is never reset (_AttemptState has only the retry-reset start_time at :979) and derive elapsed_s from it, leaving start_time to the classifier. ~3 lines plus a test at the interplay.

Why CI is green: test_2789…:258 (test_portal_attempt_ceiling_still_covers_one_worst_attempt), the test that claims to pin exactly this, is a tautology — assert svc.portal_attempt_ceiling_seconds(t) >= t + 10 + 300 reduces to t+310 >= t+310. It never invokes execute_task and cannot fail for any value of the bug. Which is this PR's own learnings.md lesson recurring inside the fix for it: "a bound-check test must be parameterised away from the coincidence."

Warnings

• test_2789…:281 proves nothing about the PR — it calls the pre-existing _classify_timeout_failure with literals and asserts a dataclass default; it survives every mutation.
• The new _AGENT_HTTP_SLACK_S is immediately duplicated as a magic 10 in client_portal/service.py:3247,3261 — the drift class the adjacent line calls out. Import it.
• _SWITCH_RETRY_DELAY_S (3s) is awaited at :2139, after elapsed_s is computed at :2085, so every SUB-003 retry overruns effective_timeout by 3s. Harmless under the old clamp; now it's on a boundary you're declaring hard.
• _log_retry_budget: with elapsed_s <= 0.0 it emits the reader-race "clamped to Ns" sentence regardless of reason — the mislabel commit 2 was pushed to remove.
• learnings.md conflict with dev (routine append) needs a rebase.

🤖 Generated with Claude Code

[dolho]

Addressed in 43bbed5d8 + a6a97787e (on top of eb578600d, the dev merge — learnings.md keep-both).

C1 — the bound now holds on the interplay, measured

You were right, and the diff's own 200-lines-later sentence is what should have stopped me. _AttemptState gains turn_started_at, set once at construction and never re-stamped; _turn_elapsed_seconds(state) reads it, and the SUB-003 budget is derived from it — after the settle delay, so the 3s counts too (W3). start_time keeps its job as the classifier's clock.

Your table, re-run on this head with a controlled clock (test_the_interplay_cannot_outrun_the_turns_budget: attempt 1 = 3000s, reader-race retry = 5s, timeout_seconds=3600):

	pre-PR	previous head	now
SUB-003 grant at t=3005	300s	3605s	605s (= 3610 − 3005)
worst wall-clock	3305s	6610s	3610s

Reverting the one line to the retry clock turns that test and the marker test red (3605s granted). The slot lease (3900s), the watchdog (3600s) and portal_attempt_ceiling_seconds (3910s) are all back on the right side of it.

The tautology

Gone. test_portal_attempt_ceiling_still_covers_one_worst_attempt (t+310 >= t+310) is replaced by test_the_portal_marker_covers_the_executed_worst_case, which executes the worst case — attempt 1 to its cap, reader-race retry to its ceiling, SUB-003 the remainder — and asserts the sum fits the marker. Same fake clock, same execute_task path. It is red on the previous head. Point taken on the learnings entry recurring inside its own fix; the entry stands, the test now obeys it.

Warnings

• W1 — the literal _classify_timeout_failure test is replaced by one that drives _handle_timeout with a state carrying applied_timeout_seconds=300 and a 300s-old start_time: TIMEOUT against 300, no "3600" in the message; and the first-attempt case (nothing applied) stays NETWORK against 3600. Mutating the effective_limit read in _handle_timeout turns it (and the e2e test) red.
• W2 — portal_attempt_ceiling_seconds imports _AGENT_HTTP_SLACK_S; no 10 left in that derivation.
• W3 — budget computed after await asyncio.sleep(_SWITCH_RETRY_DELAY_S), from the turn clock.
• W4 — _log_retry_budget takes ceiling= from the caller and says "clamped" only when a ceiling actually bound; a spend-bounded retry with zero elapsed logs the spend sentence (pinned).
• W5 — rebased; MERGEABLE.

Related suites: test_2789 (13) + test_792 + test_2106 + test_2133 — 47 passed. Honest gap I know of: the "after the settle" ordering is by construction and the interplay test patches _SWITCH_RETRY_DELAY_S to 0, so the 3s itself is not what the fake clock measures.

[dolho]

/review — head a6a97787 vs merge-base 0bddbc95 — third pass, after the train's C1

Files: 7 (+748/−25) · Scope: CLEAN — still #2789's budget, attribution and log, now with the turn clock the train review showed was missing. No new surface.
Plan completion: the approved plan's five items DONE; the train's C1 + W1–W5 DONE (previous comment cites each file:line).

Critical

None. The one that existed — the budget measured from a clock the reader-race retry resets — is closed by turn_started_at, and the closure is executed, not asserted from text: test_the_interplay_cannot_outrun_the_turns_budget drives 502 → reader-race retry → 429 → SUB-003 through execute_task on a fake clock and reads the grant off the dispatched call.

Informational

[I1] turn_started_at is Optional with a start_time fallback (Confidence 5/10)
_turn_elapsed_seconds anchors on turn_started_at or state.start_time. Every production construction sets both (execute_task:1352, the only site); the fallback exists so test_2638's two _AttemptState(start_time=NOW) constructions keep working. That is a fallback to the wrong clock, silently, for any future site that forgets the kwarg. Making turn_started_at required — or deriving it in __post_init__ from start_time when absent, which is the same value at construction — would remove the trap without touching the two tests. Not blocking; the only real construction is correct and pinned by the interplay test.

[I2] The settle delay is accounted for by ordering, not measured (Confidence 4/10)
The budget is computed after await asyncio.sleep(_SWITCH_RETRY_DELAY_S), but the interplay test patches that delay to 0 and the fake clock only advances inside the agent calls — so the 3s never appears in the measured grant. Correct by construction (the read follows the sleep); recording that no test would notice the two lines swapping back.

[I3] A hopeless retry is still dispatched (Confidence 4/10)
max(1.0, effective − elapsed) still grants a 1s HTTP / 1s agent retry when the turn is out of budget. The WARNING now names it ("under the reader-race ceiling; likely hopeless and still billed"), which is the visibility the issue asked for; whether to skip it belongs with #2638's switch policy, as the PR body says.

Clean

• The bound, stated precisely now: first attempt + reader-race retry + SUB-003 retry ≤ effective_timeout + _AUTO_RETRY_MAX_TIMEOUT_S — the reader-race retry keeps its "+300 on top" by Async chat_with_agent: long execution silently fails with null response (reader-thread) #678's own design and portal_attempt_ceiling_seconds derives exactly that; the SUB-003 retry is bounded by the turn's remainder. test_the_portal_marker_covers_the_executed_worst_case runs attempt 1 to cap + reader-race to ceiling and asserts the executed sum fits the marker.
• Classifier: _handle_timeout reads applied_timeout_seconds with an explicit is not None; driven directly (test_handle_timeout_judges_the_retry_against_its_applied_budget) and end-to-end; mutating the read turns both red.
• Log: "clamped" only with a named ceiling=; spend sentence otherwise; silent when nothing was taken; escalates to WARNING under 300s left.
• No duplicated constant: _AGENT_HTTP_SLACK_S is imported by the portal derivation.
• Adjacent suites (test_2638, test_auto_retry_reader_race, test_1804_*, test_1578, test_1083_result_callback, test_2106, test_2133, test_792, test_2789): 190 passed. The full-suite A/B from yesterday stands: the 10 test_792 full-order failures are pre-existing pollution (green in isolation and after this file), CI's base/head diff is the authority.
• Auth / credentials / SQL: untouched.

Verdict: READY. I1 is the one I would still tidy, and it is a two-line __post_init__.

[dolho]

merge-train: pushed to this branch — one commit, mechanical (the pre-validation ⚠️): test_792_subscription_retry.py re-anchored assert now reads 300 + _AGENT_HTTP_SLACK_S instead of the literal 10 this PR removed everywhere else. test_792 + test_2789: green. Nothing else touched.

[vybe]

merge-train: merged dev into this branch to resolve the docs/memory/learnings.md append collision left by the previous train member (keep both entries, theirs first). Mechanical; no other file touched.

[vybe]

merge-train: batch validated on train/20260916-0919 (train PR #2839)