cmoriarty/braid
1
0
Fork 0
Code Issues 15 Pull requests Projects Releases Packages 1 Wiki Activity Actions

The watchdog orphans a working step when its subagent finishes first: it checks the subagent's session, not the step's #141

New issue
Closed
opened 2026-10-04 21:48:25 -04:00 by cmoriarty · 2 comments
cmoriarty commented 2026-10-04 21:48:25 -04:00
Owner
Copy link

What happened

In run 44 (run_01M44PHE3XQ59GBHGRW9STWFDR, the second baseline for #139), openspec.apply[3] attempt 1 was orphaned at 01:36:11Z with "osfd died while this attempt was running". osfd had not died: it had been up on one boot since 00:12:23Z. Braid's own liveness watchdog killed a healthy attempt.

From osfd's log and the run's oc.db (UTC):

  • 01:35:07 The apply session (…DMAvfotZ) starts a test subagent, ses_ef64cb413ffekh1OvfuRzWAJ7d, "Run front-end test and build".
  • 01:35:19 The apply session begins a 3,059-token message, a large file write. A tool call's input streams no events until it completes, which it does at 01:36:36.
  • 01:35:40 The subagent finishes.
  • 01:36:11 The watchdog logs: openspec.apply[3] is running but nothing is running it — session ses_ef64cb413ffekh1OvfuRzWAJ7d has been missing from the busy map of a server that answers for 20s while the step is still running; orphaning it for §12
  • 01:36:13 Attempt 2 starts, continuing in place.
  • 01:36:36 The abort reaches the apply session. It had just finished its write, and the abort cut off the message it had started next.

Why

recovery._session_id, which the watchdog uses, takes the session of the attempt's newest logged event, so that a budget respawn's new session is found. But a subagent's events are logged on its parent's step under the subagent's own session id. Once a subagent finishes, the newest event can name the subagent. The watchdog then checks the subagent:

  • it is absent from the busy map, because it is done;
  • it has no children of its own;
  • the step is silent while the primary writes.

The working primary was never asked about.

Any step can hit this when a subagent finishes and the primary then stays silent for more than about 20 seconds, such as during a long write or while it waits for an inference slot.

Fix

  • Resolve a step's session among its primary sessions only: skip the sessions an oc.child.started event announced for the attempt. Keep newest-first, so a respawn's session still wins.
  • Say what was observed when the watchdog orphans an attempt. "osfd died" is hard-coded in recovery, and here it sent the reader looking at a restart that never happened.

Related: #70 (recovery continues in place), #69 (a step waiting on its own tool call).

## What happened In run 44 (`run_01M44PHE3XQ59GBHGRW9STWFDR`, the second baseline for #139), `openspec.apply[3]` attempt 1 was orphaned at 01:36:11Z with "osfd died while this attempt was running". osfd had not died: it had been up on one boot since 00:12:23Z. Braid's own liveness watchdog killed a healthy attempt. From osfd's log and the run's `oc.db` (UTC): - **01:35:07** The apply session (`…DMAvfotZ`) starts a `test` subagent, `ses_ef64cb413ffekh1OvfuRzWAJ7d`, "Run front-end test and build". - **01:35:19** The apply session begins a 3,059-token message, a large file write. A tool call's input streams no events until it completes, which it does at 01:36:36. - **01:35:40** The subagent finishes. - **01:36:11** The watchdog logs: `openspec.apply[3] is running but nothing is running it — session ses_ef64cb413ffekh1OvfuRzWAJ7d has been missing from the busy map of a server that answers for 20s while the step is still running; orphaning it for §12` - **01:36:13** Attempt 2 starts, continuing in place. - **01:36:36** The abort reaches the apply session. It had just finished its write, and the abort cut off the message it had started next. ## Why `recovery._session_id`, which the watchdog uses, takes the session of the attempt's newest logged event, so that a budget respawn's new session is found. But a subagent's events are logged on its parent's step under the subagent's own session id. Once a subagent finishes, the newest event can name the subagent. The watchdog then checks the subagent: - it is absent from the busy map, because it is done; - it has no children of its own; - the step is silent while the primary writes. The working primary was never asked about. Any step can hit this when a subagent finishes and the primary then stays silent for more than about 20 seconds, such as during a long write or while it waits for an inference slot. ## Fix - Resolve a step's session among its primary sessions only: skip the sessions an `oc.child.started` event announced for the attempt. Keep newest-first, so a respawn's session still wins. - Say what was observed when the watchdog orphans an attempt. "osfd died" is hard-coded in recovery, and here it sent the reader looking at a restart that never happened. Related: #70 (recovery continues in place), #69 (a step waiting on its own tool call).
cmoriarty commented 2026-10-04 22:01:50 -04:00
Author
Owner
Copy link

Fixed in watchdog-primary-session. Deployed as 25e898d at 02:00:58Z and archived in 3431a23.

  • The step's own session. When the engine works out which session an attempt is driving, it now skips the sessions an oc.child.started event announced for that attempt, nested subagents included. It still takes the newest of the step's own, so a budget respawn's new session still wins. One lookup serves four places:
    • the watchdog's liveness check;
    • recovery's observation of an orphaned step;
    • the re-issued abort;
    • the take-over of a live session after a restart, which could also have picked a subagent.
  • The true reason. An attempt the watchdog closes now says the watchdog found nothing running it: … with what it saw, the same sentence it logs. "osfd died while this attempt was running" stays for attempts a restart interrupted.

Verified

  • New tests reproduce run 44's sequence: a test subagent finishes, then the primary is busy and silent past the grace. They fail on the old lookup and pass on the fix. The existing respawn test still passes.
  • The closed attempt carries the watchdog's reason, and a restart's close still says osfd died.
  • Fast lane: 2,587 backend, 555 vitest, 166 browser tests. Full lane: 2,595, 555 and 183.

Run 44 was abandoned to deploy this. The baseline for #139 is now run 45, which started on this build.

Fixed in `watchdog-primary-session`. Deployed as 25e898d at 02:00:58Z and archived in 3431a23. - **The step's own session.** When the engine works out which session an attempt is driving, it now skips the sessions an `oc.child.started` event announced for that attempt, nested subagents included. It still takes the newest of the step's own, so a budget respawn's new session still wins. One lookup serves four places: - the watchdog's liveness check; - recovery's observation of an orphaned step; - the re-issued abort; - the take-over of a live session after a restart, which could also have picked a subagent. - **The true reason.** An attempt the watchdog closes now says `the watchdog found nothing running it: …` with what it saw, the same sentence it logs. "osfd died while this attempt was running" stays for attempts a restart interrupted. **Verified** - New tests reproduce run 44's sequence: a `test` subagent finishes, then the primary is busy and silent past the grace. They fail on the old lookup and pass on the fix. The existing respawn test still passes. - The closed attempt carries the watchdog's reason, and a restart's close still says osfd died. - Fast lane: 2,587 backend, 555 vitest, 166 browser tests. Full lane: 2,595, 555 and 183. Run 44 was abandoned to deploy this. The baseline for #139 is now run 45, which started on this build.
cmoriarty commented 2026-10-05 10:41:24 -04:00
Author
Owner
Copy link

An update since the fix:

  • The baseline is now run 47. The comment above names run 45 as #139's baseline, but run 45 was stopped before its apply steps, so the console's VERIFY & FIX band could deploy. Run 46 stopped at its third apply step when trogdor was needed for vLLM testing. Run 47 started on 2026-10-05 at 14:20Z.
  • Not yet seen in production. Since the fix deployed (2026-10-05 02:00:58Z), the watchdog has closed no attempt, and no step has started a subagent, so the case this fixes has not come up yet. Run 47's apply steps are the next chance. #139's results will say whether any of its steps had a subagent finish first, and how the watchdog judged it.
An update since the fix: - **The baseline is now run 47.** The comment above names run 45 as #139's baseline, but run 45 was stopped before its apply steps, so the console's VERIFY & FIX band could deploy. Run 46 stopped at its third apply step when trogdor was needed for vLLM testing. Run 47 started on 2026-10-05 at 14:20Z. - **Not yet seen in production.** Since the fix deployed (2026-10-05 02:00:58Z), the watchdog has closed no attempt, and no step has started a subagent, so the case this fixes has not come up yet. Run 47's apply steps are the next chance. #139's results will say whether any of its steps had a subagent finish first, and how the watchdog judged it.
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
main
archive/prefect-kestra-experiments
Labels
Clear labels
No items
No labels
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
cmoriarty/braid#141
No description provided.