Repository navigation
fix(cron): retry bot-chat delivery when the recipient is mid-turn - #107522
Open
sefsefsef10 wants to merge 5 commits into
Open
sefsefsef10 wants to merge 5 commits into
sefsefsef10 wants to merge 5 commits into
Conversation
A bot-chat delivery refused because the recipient's Bot Chat already has a live owner was treated as a terminal failure and dropped. Bot-chat is deliberately excluded from the durable delivery queue in _deliver_result (a bot turn costs money and must never be replayed by a second writer), so that drop is total: the payload exists nowhere afterwards. The sender records delivery_outcome=failed, the recipient never learns anything was sent, and a scheduled finding is lost silently. SESSION_NOT_OWNED is a typed CAPACITY refusal -- active_sessions.py documents it as "busy, come back later" -- so the correct response is to wait, not to give up. Reproduced live: two concurrent `hermes chat -c "Bot Chat"` sends against one profile return exit 1 / SESSION_NOT_OWNED for the second, which is exactly what a bot routine firing during another bot's delivery turn produces. Observed in the field with two routines 30 minutes apart whose recipient turn ran 15 minutes. Retry only the typed capacity refusals (SESSION_NOT_OWNED, MAX_CONCURRENT_SESSIONS) with exponential backoff; genuine failures stay terminal and loud on the first attempt, and an exhausted ladder still returns the refusal rather than a phantom success. Defaults (3 retries; 30s doubling to 30/60/120s) are sized for an agent turn and live in config.yaml, not env vars; bot_chat_busy_retries: 0 restores the previous drop-on-busy behaviour. Tests: a busy recipient is retried and delivers; a genuine error is attempted exactly once; a persistently busy recipient reports the refusal instead of succeeding.
Two defects in the busy-retry gate, both found by adversarial review: 1. Substring matching meant ANY child output containing "SESSION_NOT_OWNED" was retried -- including a job whose own payload or traceback merely mentions the reason name. Parse the `hermes-refusal-reason:` marker line the CLI actually emits (hermes_cli/active_sessions.py) instead. 2. The output was truncated to its last 500 chars BEFORE classification. The refusal marker is printed FIRST, ahead of the CLI's long explanatory text, so a real refusal behind a verbose message was classified as a genuine failure and the payload dropped -- the precise bug the retry exists to prevent. Classify on the full output; truncate only what is displayed. SESSION_COORDINATION_UNAVAILABLE is now explicitly excluded and pinned by a test: it means ownership could not be PROVEN, and retrying an unprovable state is the fail-open hole that lets two writers share one session. Duplicate delivery was investigated and does not occur: a capacity refusal is issued at lease acquisition, before any turn runs. Verified live -- a refused concurrent send wrote 0 rows to the recipient's state.db. A timeout after acceptance exits through `except subprocess.TimeoutExpired` and never reaches the retry path. Tests: 23 pass. Reverting either fix fails exactly the two tests that guard it (mutation-verified).
Each retry attempt carries its own delivery timeout, so the retry ladder had no overall ceiling: a recipient whose turns HANG rather than refuse could stack 4x600s of timeout plus 210s of backoff -- ~44 minutes inside a single delivery, holding a cron worker the whole time. Measured live on the real CLI: a capacity refusal returns in ~3.4s (a successful delivery ~9.8s), so the realistic ladder costs ~4 minutes and is unaffected. The ceiling exists for the pathological case only. cron.bot_chat_busy_budget_seconds (default 900) is checked BEFORE starting another sleep, so it never truncates a delivery that is progressing -- it only declines to sleep into time it cannot honour. 0 disables it. Tests: 25 pass. Removing the guard fails exactly the budget test; a fast ladder at the measured 3.4s latency still retries and delivers.
The busy-retry backoff slept up to 210s in one uninterruptible time.sleep. Gateway stop marks in-flight cron executions interrupted and then drains for agent.cron_drain_timeout (default 30s), so a worker merely WAITING to retry was still sleeping when the drain gave up -- SIGKILLed mid-wait and left wedged instead of cleanly interrupted. The retry that exists to save a delivery could therefore cost a clean shutdown. Sleep in <=1s slices and poll cron.scheduler._is_interrupted (the existing non-destructive peek used elsewhere before deciding what to deliver), keyed by the execution's fire token so a recurring job's later run is not poisoned. Verified live: a 120s wait aborts in 0.00s once the flag is set, well inside the 30s drain. Two review-process notes, both self-inflicted and fixed here: - I first called a helper that does not exist (_is_job_interrupted) behind a bare `except Exception: pass`, which would have swallowed the mistake forever and silently disabled the guard. The except is gone; the real name is _is_interrupted. - Tests stubbing time.sleep as a no-op busy-spun against the real clock once the sleep became sliced. They now patch the _sleep_unless_interrupted seam, which is what the retry path actually calls. Tests: 27 pass in ~6s. Removing the interrupt check makes the shutdown test hang until the runner is killed (exit 124) -- the wedged-worker bug reproduced.
Independent review (different model family) returned BLOCK on ca44cc4 and was correct. The budget was checked only before SLEEPING, so the next attempt still started with a full per-attempt timeout regardless of time remaining. Reproduced: two attempts at 600s each against a 900s budget = 1230s elapsed, a 330s overshoot of the ceiling the config advertises. The budget is now a deadline. Each attempt's timeout is clamped to the time actually left, and a TimeoutExpired caused by that clamp is reported as budget exhaustion rather than as the recipient hanging for the full configured timeout -- the two are different failures and must not be conflated. The more serious finding was the test, not the code: the previous budget test asserted only `attempts < 4`, which passed while elapsed time was 1230s. It tested a proxy instead of the invariant. It now asserts elapsed <= budget and that a later attempt is clamped, and a second test pins the budget-vs-hang error distinction. Reverting the clamp fails both. Tests: 28 pass.
alt-glitch
added
type/bug
Related: #102659 (open) also retries cron bot-chat delivery on live-owner refusals via the relay turn lock, and #100319 (open) queues delivery for CLI-only owners. This PR instead classifies the typed |
This branch has not been deployed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The bug
A cron delivery to
bot-chat:<profile>is dropped when the recipient's Bot Chat is mid-turn. The payload then exists nowhere: bot-chat is deliberately excluded from the durable delivery queue in_deliver_result(cron/scheduler_delivery.py:1673), so nothing retries it. The sender recordsdelivery_outcome=failed, the recipient never learns anything was sent, and a scheduled finding is lost silently.SESSION_NOT_OWNEDis a typed capacity refusal —hermes_cli/active_sessions.pydocuments it as "Capacity = busy, come back later" — so giving up on it discards a payload the CLI explicitly invited us to retry.Reproduced live (Windows, real CLI): two concurrent
hermes chat --in ~ -c "Bot Chat" -Qsends against one profile; the second returns exit 1 withhermes-refusal-reason: SESSION_NOT_OWNED. Observed in the field with two bot routines 30 min apart whose recipient turn ran 15 min.The fix
Retry only typed capacity refusals (
SESSION_NOT_OWNED,MAX_CONCURRENT_SESSIONS) with exponential backoff. Genuine errors stay terminal and loud on the first attempt.Four commits, each fixing a defect found by review rather than by writing the code:
11d6448— retry capacity refusals instead of dropping them.b795c41— classify by parsing thehermes-refusal-reason:marker, not substring-matching output. Also fixes classification running on output already truncated to its last 500 chars — the marker prints first, so a real refusal behind a verbose message was misread as a hard failure and the payload dropped. Classify on full output; truncate only what is displayed.SESSION_COORDINATION_UNAVAILABLEis explicitly excluded (ownership unprovable is not busy; retrying it is the fail-open hole).ea2d1f2— make the retry wait yield to gateway shutdown. The backoff slept up to 210s uninterruptibly while stop drains cron foragent.cron_drain_timeout(default 30s), so a worker merely waiting was SIGKILLed mid-wait and left wedged. Now sleeps in ≤1s slices polling the existing_is_interruptedpeek, keyed by fire token.99fef31— make the budget a real deadline. It was checked only before sleeping, so the next attempt still got a full per-attempt timeout regardless of time left: 1230s elapsed against a 900s budget. Each attempt's timeout is now clamped to remaining time, and a timeout caused by that clamp reports budget exhaustion rather than "the recipient hung" — different failures.Config (
config.yaml, not env vars)cron.bot_chat_busy_retries30restores previous drop-on-busycron.bot_chat_busy_backoff_seconds30.0cron.bot_chat_busy_budget_seconds900.00disablesMeasured live: a capacity refusal returns in ~3.4s (successful delivery ~9.8s), so the realistic ladder costs ~4 min. The budget exists for the pathological hang case only.
Not changed, and why
state.db.TimeoutExpiredexits through the outer handler and never reaches the retry loop. So retrying cannot duplicate a paid bot turn.tick(sync=False)submits to aThreadPoolExecutorand releases.tick.lockwithout waiting; the sleep occupies one worker.Tests
tests/cron/test_cron_bot_chat_delivery.py— 28 pass.Each fix is pinned by a test that fails when reverted:
The budget test previously asserted only
attempts < 4and passed while elapsed time was 1230s against a 900s budget — a proxy, not the invariant. It now assertselapsed <= budgetand that a later attempt is clamped.scripts/run_tests.sh tests/cron/shows 11 failures on this Windows host that are identical on cleanorigin/main(pre-existing env issues, unrelated to this change).