Skip to content

fix(orchestrator): capture sidecar stderr + raise default boot timeout (closes #1) - #2

Open
evannadeau wants to merge 1 commit into
SpawnBox-dev:mainfrom
evannadeau:fix/sidecar-boot-timeout-and-log-capture
Open

fix(orchestrator): capture sidecar stderr + raise default boot timeout (closes #1)#2
evannadeau wants to merge 1 commit into
SpawnBox-dev:mainfrom
evannadeau:fix/sidecar-boot-timeout-and-log-capture

Conversation

@evannadeau

@evannadeau evannadeau commented Apr 26, 2026

Copy link
Copy Markdown

Closes #1.

Three changes against mcp/server.ts, plus the rebuilt dist/server.js:

  1. Sidecar stdout/stderr → <pluginRoot>/.sidecar.log (truncated each boot). trySpawn accepts a log FD; replaces stdio: "ignore". FD opened once in startSidecar, shared across all uvx → python → python3 fallback attempts. Falls back to "ignore" if openSync throws — preserves prior behavior on open failure.
  2. ORCH_SIDECAR_BOOT_TIMEOUT_MS env override + uvx default 60 s → 180 s. Eliminates the residential-link failure described in orchestrator: silent sidecar boot failure on first install_embeddings — 60s timeout exceeded by cold-start downloads #1. Python/python3 fallback timeouts honor the env var but default unchanged at 30 s (assumes uvx already cached deps).
  3. system_status and install_embeddings now reference the log path and, when the bge-m3 model isn't yet cached, suggest the timeout env var. install_embeddings(check) adds a bge-m3 model cache: present (~10s boot expected) | not yet downloaded (~2 GB on first boot) line that disambiguates first-run from broken-run.

.gitignore picks up .sidecar.log. dist/server.js rebuilt via bun run build.

Tested

  • bun run typecheck — clean.
  • bun test — 330 pass / 1 fail. The single failure is in tests/hooks/hooks.test.ts (session-activity-nudge text mismatch) and reproduces against upstream/main without this patch — pre-existing, not introduced here.
  • Cold-start verified end-to-end on residential broadband (~100 Mbps WSL2). Reconstructed timing from process lstart + HF cache blob mtimes:
    • 10:00:41 — cold sidecar boot started (HF cache empty)
    • 10:01:54 — 2.27 GB model.onnx_data finished downloading (73 s in)
    • ~10:02:02 — Model ready, port file written, sidecar healthy (~80 s total)
    • The prior 60 s budget would have killed the spawn at 10:01:41, mid-download.
  • .sidecar.log captured the previously-discarded boot diagnostics (download progress, HF rate-limit warning, ONNX load, port write, "Listening on …").
  • install_embeddings(check) with cache populated returned the expected bge-m3 model cache: present (~10s boot expected) line.

Known minor limitation

.sidecar.log opens in "w" mode per startSidecar call, so a second startSidecar (e.g. on install_embeddings(install) after an automatic session-start spawn) truncates the prior attempt's log. Strictly better than stdio: "ignore", but consider switching to "a" (append) or rotate-on-open if maintainers want multi-attempt forensics. Happy to follow up.

Not changed

  • No version bump — leaving that to maintainer judgment.
  • No new tests — adding integration tests for spawn/log behavior would be heavy. Existing suite + manual cold-start cover the change.
  • No README/docs changes — the env var surfaces in install_embeddings(install) failure output, which is where users hit it.

Evan Nadeau @evannadeau
fix(orchestrator): capture sidecar stderr + raise default boot timeout (
8a02a08 
closes #1)

Three changes to mcp/server.ts make the sidecar boot path self-diagnosing
on slow connections and configurable for users who need more time:

1. Capture spawned-sidecar stderr to <pluginRoot>/.sidecar.log instead of
   stdio: "ignore". File opened (truncated) once per startSidecar call,
   shared across all uvx/python/python3 fallback attempts. Falls back to
   "ignore" if openSync throws — preserves prior behavior on open failure.

2. Raise default uvx boot timeout 60s → 180s; expose
   ORCH_SIDECAR_BOOT_TIMEOUT_MS env override applied to all spawn attempts.
   Eliminates the residential-broadband failure where downloading
   ~2 GB of bge-m3 model + onnxruntime wheels exceeds the prior budget.
   Fast-link users see no behavior change (boot still completes well inside
   180s on gigabit).

3. system_status and install_embeddings now reference the sidecar log path
   and, when the bge-m3 model isn't yet cached, suggest the timeout env var.
   install_embeddings(check) adds a "bge-m3 model cache: present /
   not yet downloaded" line that disambiguates first-run from broken-run.

.gitignore picks up .sidecar.log. dist/server.js rebuilt via `bun run build`.

Refreshed 2026-05-13: rebased onto upstream/main (78 commits of orchestrator
churn since open, v0.25.x → v0.30.38). Rebase was conflict-free; dist/server.js
regenerated from rebased source (textual three-way merge of generated artifacts
isn't authoritative). The prior commit's "330 pass / 1 fail (pre-existing —
hooks.test.ts session-activity)" footer no longer applies; the suite has grown
and that failure was resolved upstream.

bun run typecheck: clean.
bun test: 516 pass / 0 fail (38 files, 1207 expect() calls).
@evannadeau
evannadeau force-pushed the fix/sidecar-boot-timeout-and-log-capture branch from 220d63f to 8a02a08 Compare May 13, 2026 21:21
@evannadeau evannadeau mentioned this pull request May 14, 2026
Closed
SpawnBox-dev pushed a commit that referenced this pull request Jul 13, 2026
SpawnBox-dev @claude
fix(orchestrator): rebuild stale dist (activates 0.30.56-0.30.65) + e…
4ede068 
…gress-death detection + build-gate - 0.30.66

CRITICAL: dist/server.js was stale since 0.30.55 (Jun 10). Nine mcp/ commits
(compaction rework, flap-storm fix, warden liveness nudge, turnsSinceMarker,
egress detection) were committed + version-bumped + published WITHOUT a
`bun run build`, so every live session executed the Jun-10 bundle - a month of
shipped-but-inert code. Today's mass false-departures were the unfixed flap +
egress-loss. Caught by a code-reviewer on the egress diff (risk 206a0af3).
0.30.66 is the FIRST bundle carrying 0.30.56-0.30.65's accumulated code.

New this ship (WI 0f9dcd95): deterministic egress-death detection. classifyAbsence
distinguishes egress-dead (alive: transcript grew after heartbeat went stale ->
egress_suspect, held, never reaped) from genuinely-gone (frozen -> session_departed).
Review finding #2 (recoverable-stall false-positive) accepted + documented + locked
by a self-heal integration test.

Prevention (so this bundle-staleness class can't recur):
- tests/dist-freshness.test.ts FAILS in `bun test` when dist/server.js is older
  than the newest mcp/ source - a stale bundle can no longer pass the suite.
- CLAUDE.md "Publish checklist" puts `bun run build` FIRST in the bump-and-ship flow.

Suite 643 pass / tsc clean. Fleet adoption: /plugin update + /mcp reconnect.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015h2MkJuBxKUxJzSooeScJ5
SpawnBox-dev pushed a commit that referenced this pull request Jul 13, 2026
SpawnBox-dev @claude
feat(orchestrator): ingress-death (parked-loop) detection - 0.30.67
92d6b50 
Sibling of the 0.30.66 egress detector, for the INVERSE failure (WI 19294811,
live incident 2026-07-13). A session PRESENT in the roster (heartbeat fresh) can
have its event loop PARKED - confirmed cause: an interactive menu/prompt left
open (an open /mcp menu parks the loop). Its bun keeps heartbeating and the
filewatcher keeps ENQUEUEing channel deliveries, but no turn runs to DEQUEUE
them. Both heartbeat and transcript-growth are false-negatives; only a delivery
enqueued-but-never-dequeued since the last real activity reveals it. Session
a3bb12a4 ran no turn for 40+ min while five deliveries (two addressed to it)
piled unprocessed; caught only by PA transcript-tailing.

Detection is PEER-SIDE ONLY: a self-emit rides server.server.notification() ->
the parked local harness, which can't drain the MCP transport until the park
clears, so it could never escape its own park. Advisory-only; never reaps.

- parseIngressTail: oldest enqueue unmatched by a dequeue since the last real
  entry (FIFO-matched), + a lastRealIsMidTurn signal.
- classifyIngress: ingress_suspect when fresh + orphan older than 3 min + not
  mid-turn; throttled 30s tail scan in tick().
- Remediation surface: "check that terminal for an open menu/prompt -
  Enter/Escape, then /mcp if still dead."

Adversarial code-review (2 rounds) folded in, all empirically verified against a
real 40MB transcript:
- FP #1 (long tool call, e.g. cargo build / deploy - routine here, often >3min):
  appends nothing between tool_use and tool_result -> looked like a park.
- FP #2 (extended thinking): same silent-blocked shape, no tool block.
Both closed by the mid-turn guard: the LAST real entry being a `user` entry
(owes a response / extended-thinking) OR an `assistant` with a tool_use block
(tool running) => alive, suppress. Scoping to the last real entry (not a
whole-window tool balance) also avoids a persistence false-negative a balance
would have had. Reviewer's #2/#3 hardenings included (absent-peer clear;
no re-arm on transient read failure).

Suite 666 pass / tsc clean. Design: docs/2026-07-13-ingress-death-detection-design.md.
Fleet adoption: /plugin update + /mcp reconnect.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015h2MkJuBxKUxJzSooeScJ5
SpawnBox-dev pushed a commit that referenced this pull request Jul 13, 2026
SpawnBox-dev @claude
fix(orchestrator): warden-nudge threshold+framing + loop-close scope …
8f7a02a 
…(PA findings #2,#3) - 0.30.69 follow-up

Two live-sourced plugin fixes from PA's warden experience this session (note
c8d00f21, Jarid-routed). Ride the undeployed 0.30.69 batch.

#2 - warden-liveness nudge was too aggressive (hook_event.ts):
- WARDEN_STALE_THRESHOLD_MS 420_000 (~7min) -> 900_000 (~15min). The 7-min fire
  pushed PA into 3 premature respawns this session - a big-delta pass reads the
  fleet's transcripts for ~9min BEFORE writing, so mtime stays frozen mid-pass.
- Softened the stale text from "PRESUMED DEAD/STUCK. Respawn." to poke-first:
  a stale mtime may be a slow-but-live warden; SendMessage-poke revives (slowly),
  check for a mid-pass signal, respawn only if truly frozen. Matches the c45d5a6
  brief correction (the plugin nudge had contradicted the brief).

#3 - loop-close nudge over-attribution (hook_event.ts):
- listInFlightWorkItemsForSession counted 'proposed'/'planned' (queued,
  not-started) items as in-flight, nagging every turn about deferred work that
  isn't a loop to close. Now excludes proposed/planned/terminal statuses, so only
  genuinely in-flight work surfaces.

Suite 672 pass / tsc clean. Tests updated (stale-nudge now asserts poke-first,
not presumed-dead) + new regression (a proposed WI does not trigger loop-close).
Root-cause #1 (warden pass-in-progress marker) captured for the liveness phase.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015h2MkJuBxKUxJzSooeScJ5
SpawnBox-dev pushed a commit that referenced this pull request Jul 27, 2026
SpawnBox-dev @claude
fix(orchestrator): 0.30.92 - briefing 240s+ -> 0.22s; unblock the mai…
c6959ee 
…ntenance pass that has been silently rolling itself back

Three defects, found by profiling the live 6,827-note / 959K-link project DB
after PA called out that the prior-art sweep and the briefing timeout had been
deferred through nineteen releases. None was on anyone's list an hour ago.

1. THE BRIEFING TIMEOUT - an N+1, not corpus size. Four of six sessions
   reported briefing() blowing the 120s budget, on the one call every session
   must make before it is allowed to respond.

   Found by COUNTERFACTUAL rather than inspection: timing sections separately
   showed work_items / open_threads / decisions at ~0.1s each while `neglected`
   ALONE exceeded 240s. That section built the set of distinct tags, then ran
   one `SELECT COUNT(*) ... WHERE tags LIKE '%tag%'` PER TAG. A leading
   wildcard admits no index, so each iteration was a full table scan: 8,888
   tags over 6,827 notes.

   Rewritten as a single pass - read tags + updated_at once, record most-recent
   activity per tag in a map. MEASURED AFTER: neglected 0.07s, FULL BRIEFING
   0.22s.

   SEMANTIC FIX included and deliberate: the old count matched by SUBSTRING
   (`LIKE '%map%'` satisfied by a note tagged `roadmap`) while the tag set was
   built with parseTagList, so a tag could be judged "active" on the strength
   of an unrelated tag containing it, and never reported. Now exact equality on
   both sides - expect a few tags to newly appear as neglected.

2. mergeDuplicates THREW SQLITE_CONSTRAINT_UNIQUE ON REAL DATA, and took the
   whole weekly maintenance pass down with it. `links` carries
   UNIQUE(from_note_id, to_note_id, relationship); re-pointing a victim's edges
   at the survivor collides on any shared neighbour, which at ~140 links per
   note is a certainty rather than an edge case. The de-dup cleanup written to
   handle exactly that collision ran AFTER the statement that died. Now
   UPDATE OR IGNORE, then drop the victim's residual edges, and group the final
   de-dup by the FULL unique key (grouping by (from,to) alone deleted distinct
   relationship edges the index explicitly permits).

3. DECAY HAS NEVER PERSISTED. reflect wrapped decayAllSignals AND
   mergeDuplicates in ONE transaction, so #2's throw rolled the decay back too,
   silently, for as long as the collision condition has held - the weekly pass
   that exists to keep the KB coherent was reverting its own work, and the only
   observable was a slow briefing. Split into separate transactions. This is
   the mechanical cause of "the KB doesn't stay current": no agent could have
   compensated by being more diligent.

Also: the auto-retro invoked INLINE by briefing now passes skip_merge. Measured,
mergeDuplicates takes 61.2s to merge 2 notes and remove 76 links out of
959,125 - it finds almost nothing because the write-time check_similar gate
already blocks duplicates before they land. An explicit `retro` still runs it;
it no longer sits on the hot path of a hard-gated call.

TWO CORRECTIONS TO MY OWN CLAIMS THIS SESSION, both from counterfactuals:
- I said the 61.2s merge "is the timeout". It is not - with merge skipped the
  path STILL exceeded 120s. A measured number attached to an inferred
  conclusion; the counterfactual is what settled it.
- PA hypothesised link saturation was downstream of the broken merge, and that
  `neglected` might be downstream of decay never running. Both falsified: a
  successful merge removed 76 links of 959,125, and `neglected` is computed
  purely from tags and updated_at, never touching signal. Three independent
  defects, not one ratchet.

Tests: +6 (neglected reports stale / spares recent / one recent note rescues a
mixed tag / the substring-collision semantic fix / a linearity guard so the N+1
cannot return; plus the merge collision shape, asserting no throw, exactly one
surviving edge, and no dangling references). Suite 800 pass / 0 fail.

STILL OPEN, stated so this does not read as more than it is: 9,343 neglected
areas across 6,827 notes is unactionable output even at 0.07s, and 959K links
remain - the 0.30.73 cap bounds NEW notes only. Both are shape problems, not
speed problems, and are tracked rather than fixed here.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01MLELREep1GfMbuPSpmJRcu
SpawnBox-dev pushed a commit that referenced this pull request Jul 27, 2026
SpawnBox-dev @claude
fix(orchestrator): 0.30.93 - egress_suspect keeps the signal, drops t…
fd6517c 
…he diagnosis

Third alert this session rewritten from conclusion to question, and a NEW
failure mode underneath it that is not on tonight's list.

WHAT HAPPENED: Jarid's /reload-plugins restarted every MCP server. PA's
heartbeat lapsed for a few seconds while its transcript kept growing - which is
precisely the egress-death signature - and egress_suspect fired. A peer
escalated it to Jarid, asking him to run /mcp at a terminal that was already
healthy.

THE NEW FAILURE MODE (PA's framing, and it is distinct from everything else
found tonight): both measurements were ACCURATE and the TENSE was wrong. A
transient state reported as a persistent one. Every other case this session was
a check that could not discriminate; this one discriminated correctly about a
moment that had already passed. The discriminator is nearly free - RE-SAMPLE.
A single reading cannot separate a broken transport from a RESTARTING one; a
second reading thirty seconds later can, and is especially worth taking right
after something restarted the transport.

DELIBERATELY NOT SUPPRESSED. The code already documents this as an ACCEPTED
false positive (0.30.66 review finding #2): a recoverable MCP wedge that
self-heals also grows-while-stale and trips it once, tolerated because the
alert is advisory, never reaps, and suppressing it would risk muting a real
egress death. That reasoning stands and this change does not override it.

WHAT CHANGED IS THE EVIDENCE ABOUT ITS COST. That decision assessed a
self-healing trip as "a benign one-off check-on-X nudge". Observed tonight, it
converts into a human interrupting a working session - the same escalation harm
the ingress alert caused before 0.30.77, and the reason that one was rewritten.
A nudge is not benign when its recipient's correct-looking next step is to page
the user.

So the text now leads with re-sampling, names /reload-plugins - /mcp - plugin
updates as expected causes, and puts "tell the user to run /mcp" LAST, after the
condition survives two readings. Same shape as 0.30.77: the signal still fires,
it just no longer arrives pre-formatted as a conclusion with a physical remedy
attached, which is what makes careful agents relay it.

No behaviour change to detection - classifyAbsence is untouched, so the existing
egress tests still pin the logic. Suite 800 pass / 0 fail.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01MLELREep1GfMbuPSpmJRcu
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

orchestrator: silent sidecar boot failure on first install_embeddings — 60s timeout exceeded by cold-start downloads

1 participant

@evannadeau