From f421157056aceeda29142b4ab9a263cf89c679bf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?T=C3=82CHES?= Date: Fri, 20 Mar 2026 09:13:23 -0600 Subject: [PATCH] =?UTF-8?q?fix(gsd):=20harden=20auto-mode=20agent=20loop?= =?UTF-8?q?=20=E2=80=94=20session=20teardown,=20unit=20correlation,=20side?= =?UTF-8?q?car=20perf=20(#1592)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Address six convergent audit findings in the auto-mode agent loop: 1. Move rewriteAttemptCount to AutoSession — eliminates module-level state that leaked across stop/start cycles in auto-dispatch.ts 2. Add unit correlation to agent_end queue — tag events with unitId so late completions from unit A cannot falsely resolve unit B 3. Split post-unit into heavy/light paths — sidecars skip settle delay, doctor, state rebuild, and worktree sync; reduce sleep 500ms→100ms 4. Data-driven budget thresholds — consolidate 75/80/90% copy-pasted notification blocks into BUDGET_THRESHOLDS array lookup 5. Fix session teardown — stopAuto() restores model first then calls s.reset() replacing 36 lines of manual field clearing 6. Add debugLog to 12 silent catch blocks in auto-post-unit.ts Co-authored-by: Claude Opus 4.6 (1M context) --- src/resources/extensions/gsd/auto-dispatch.ts | 14 +- src/resources/extensions/gsd/auto-loop.ts | 133 +++++++++--------- .../extensions/gsd/auto-post-unit.ts | 94 +++++++------ src/resources/extensions/gsd/auto.ts | 43 ++---- src/resources/extensions/gsd/auto/session.ts | 6 +- 5 files changed, 147 insertions(+), 143 deletions(-) diff --git a/src/resources/extensions/gsd/auto-dispatch.ts b/src/resources/extensions/gsd/auto-dispatch.ts index f27286da3..d04687307 100644 --- a/src/resources/extensions/gsd/auto-dispatch.ts +++ b/src/resources/extensions/gsd/auto-dispatch.ts @@ -62,6 +62,7 @@ export interface DispatchContext { midTitle: string; state: GSDState; prefs: GSDPreferences | undefined; + session?: import("./auto/session.js").AutoSession; } interface DispatchRule { @@ -82,26 +83,23 @@ function missingSliceStop(mid: string, phase: string): DispatchAction { // ─── Rewrite Circuit Breaker ────────────────────────────────────────────── const MAX_REWRITE_ATTEMPTS = 3; -let rewriteAttemptCount = 0; -export function resetRewriteCircuitBreaker(): void { - rewriteAttemptCount = 0; -} // ─── Rules ──────────────────────────────────────────────────────────────── const DISPATCH_RULES: DispatchRule[] = [ { name: "rewrite-docs (override gate)", - match: async ({ mid, midTitle, state, basePath }) => { + match: async ({ mid, midTitle, state, basePath, session }) => { const pendingOverrides = await loadActiveOverrides(basePath); if (pendingOverrides.length === 0) return null; - if (rewriteAttemptCount >= MAX_REWRITE_ATTEMPTS) { + const count = session?.rewriteAttemptCount ?? 0; + if (count >= MAX_REWRITE_ATTEMPTS) { const { resolveAllOverrides } = await import("./files.js"); await resolveAllOverrides(basePath); - rewriteAttemptCount = 0; + if (session) session.rewriteAttemptCount = 0; return null; } - rewriteAttemptCount++; + if (session) session.rewriteAttemptCount++; const unitId = state.activeSlice ? `${mid}/${state.activeSlice.id}` : mid; return { action: "dispatch", diff --git a/src/resources/extensions/gsd/auto-loop.ts b/src/resources/extensions/gsd/auto-loop.ts index b0245ed1a..4c0941160 100644 --- a/src/resources/extensions/gsd/auto-loop.ts +++ b/src/resources/extensions/gsd/auto-loop.ts @@ -18,7 +18,7 @@ import type { GSDPreferences } from "./preferences.js"; import type { SessionLockStatus } from "./session-lock.js"; import type { GSDState } from "./types.js"; import type { CloseoutOptions } from "./auto-unit-closeout.js"; -import type { PostUnitContext } from "./auto-post-unit.js"; +import type { PostUnitContext, PreVerificationOpts } from "./auto-post-unit.js"; import type { VerificationContext, VerificationResult, @@ -36,6 +36,19 @@ import type { CmuxLogLevel } from "../cmux/index.js"; */ const MAX_LOOP_ITERATIONS = 500; +/** Data-driven budget threshold notifications (75/80/90%). The 100% case is + * handled inline because it requires break/pause/stop control flow. */ +const BUDGET_THRESHOLDS: Array<{ + pct: number; + label: string; + notifyLevel: "info" | "warning"; + cmuxLevel: "progress" | "warning"; +}> = [ + { pct: 90, label: "Budget 90%", notifyLevel: "warning", cmuxLevel: "warning" }, + { pct: 80, label: "Approaching budget ceiling — 80%", notifyLevel: "warning", cmuxLevel: "warning" }, + { pct: 75, label: "Budget 75%", notifyLevel: "info", cmuxLevel: "progress" }, +]; + // ─── Types ─────────────────────────────────────────────────────────────────── /** @@ -96,10 +109,11 @@ export function resolveAgentEnd(event: AgentEndEvent): void { debugLog("resolveAgentEnd", { status: "queued", queueLength: s.pendingAgentEndQueue.length + 1, + unitId: s.currentUnit?.id, warning: "agent_end arrived between loop iterations — queued for next runUnit", }); - s.pendingAgentEndQueue.push(event); + s.pendingAgentEndQueue.push({ ...event, unitId: s.currentUnit?.id }); } } @@ -166,14 +180,37 @@ export async function runUnit( ]; } if (s.pendingAgentEndQueue.length > 0) { - const queued = s.pendingAgentEndQueue.shift()!; + // Find an event matching this unit; discard stale events from other units + const matchIdx = s.pendingAgentEndQueue.findIndex( + (e) => !e.unitId || e.unitId === unitId, + ); + if (matchIdx >= 0) { + // Discard any stale events before the match + if (matchIdx > 0) { + debugLog("runUnit", { + phase: "discarded-stale-events", + count: matchIdx, + unitType, + unitId, + }); + } + const queued = s.pendingAgentEndQueue.splice(0, matchIdx + 1).pop()!; + debugLog("runUnit", { + phase: "drained-queued-event", + unitType, + unitId, + queueRemaining: s.pendingAgentEndQueue.length, + }); + return { status: "completed", event: queued }; + } + // No matching event — discard all stale events and proceed to new session debugLog("runUnit", { - phase: "drained-queued-event", + phase: "discarded-all-stale-events", + count: s.pendingAgentEndQueue.length, unitType, unitId, - queueRemaining: s.pendingAgentEndQueue.length, }); - return { status: "completed", event: queued }; + s.pendingAgentEndQueue = []; } // ── Session creation with timeout ── @@ -383,6 +420,7 @@ export interface LoopDeps { midTitle: string; state: GSDState; prefs: GSDPreferences | undefined; + session?: AutoSession; }) => Promise; runPreDispatchHooks: ( unitType: string, @@ -500,6 +538,7 @@ export interface LoopDeps { // Post-unit processing postUnitPreVerification: ( pctx: PostUnitContext, + opts?: PreVerificationOpts, ) => Promise<"dispatched" | "continue">; runPostUnitVerification: ( vctx: VerificationContext, @@ -977,62 +1016,26 @@ export async function autoLoop( ctx.ui.notify(`${msg} Continuing (enforcement: warn).`, "warning"); deps.sendDesktopNotification("GSD", msg, "warning", "budget"); deps.logCmuxEvent(prefs, msg, "warning"); - } else if (newBudgetAlertLevel === 90) { - s.lastBudgetAlertLevel = - newBudgetAlertLevel as AutoSession["lastBudgetAlertLevel"]; - ctx.ui.notify( - `Budget 90%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", + } else { + // Data-driven 75/80/90% threshold notifications + const threshold = BUDGET_THRESHOLDS.find( + (t) => newBudgetAlertLevel === t.pct, ); - deps.sendDesktopNotification( - "GSD", - `Budget 90%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", - "budget", - ); - deps.logCmuxEvent( - prefs, - `Budget 90%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", - ); - } else if (newBudgetAlertLevel === 80) { - s.lastBudgetAlertLevel = - newBudgetAlertLevel as AutoSession["lastBudgetAlertLevel"]; - ctx.ui.notify( - `Approaching budget ceiling — 80%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", - ); - deps.sendDesktopNotification( - "GSD", - `Approaching budget ceiling — 80%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", - "budget", - ); - deps.logCmuxEvent( - prefs, - `Budget 80%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "warning", - ); - } else if (newBudgetAlertLevel === 75) { - s.lastBudgetAlertLevel = - newBudgetAlertLevel as AutoSession["lastBudgetAlertLevel"]; - ctx.ui.notify( - `Budget 75%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "info", - ); - deps.sendDesktopNotification( - "GSD", - `Budget 75%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "info", - "budget", - ); - deps.logCmuxEvent( - prefs, - `Budget 75%: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`, - "progress", - ); - } else if (budgetAlertLevel === 0) { - s.lastBudgetAlertLevel = 0; + if (threshold) { + s.lastBudgetAlertLevel = + newBudgetAlertLevel as AutoSession["lastBudgetAlertLevel"]; + const msg = `${threshold.label}: ${deps.formatCost(totalCost)} / ${deps.formatCost(budgetCeiling)}`; + ctx.ui.notify(msg, threshold.notifyLevel); + deps.sendDesktopNotification( + "GSD", + msg, + threshold.notifyLevel, + "budget", + ); + deps.logCmuxEvent(prefs, msg, threshold.cmuxLevel); + } else if (budgetAlertLevel === 0) { + s.lastBudgetAlertLevel = 0; + } } } else { s.lastBudgetAlertLevel = 0; @@ -1103,6 +1106,7 @@ export async function autoLoop( midTitle: midTitle!, state, prefs, + session: s, }); if (dispatchResult.action === "stop") { @@ -1661,9 +1665,12 @@ export async function autoLoop( break; } - // Run pre-verification for the sidecar unit + // Run pre-verification for the sidecar unit (lightweight path) + const sidecarPreOpts: PreVerificationOpts = item.kind === "hook" + ? { skipSettleDelay: true, skipDoctor: true, skipStateRebuild: true, skipWorktreeSync: true } + : { skipSettleDelay: true, skipStateRebuild: true }; const sidecarPreResult = - await deps.postUnitPreVerification(postUnitCtx); + await deps.postUnitPreVerification(postUnitCtx, sidecarPreOpts); if (sidecarPreResult === "dispatched") { // Pre-verification caused stop/pause debugLog("autoLoop", { diff --git a/src/resources/extensions/gsd/auto-post-unit.ts b/src/resources/extensions/gsd/auto-post-unit.ts index efaee75d6..c569c6a8c 100644 --- a/src/resources/extensions/gsd/auto-post-unit.ts +++ b/src/resources/extensions/gsd/auto-post-unit.ts @@ -33,7 +33,6 @@ import { writeUnitRuntimeRecord, clearUnitRuntimeRecord } from "./unit-runtime.j import { runGSDDoctor, rebuildState, summarizeDoctorIssues } from "./doctor.js"; import { recordHealthSnapshot, checkHealEscalation } from "./doctor-proactive.js"; import { syncStateToProjectRoot } from "./auto-worktree-sync.js"; -import { resetRewriteCircuitBreaker } from "./auto-dispatch.js"; import { isDbAvailable } from "./gsd-db.js"; import { consumeSignal } from "./session-status-io.js"; import { @@ -56,6 +55,13 @@ import { join } from "node:path"; /** Throttle STATE.md rebuilds — at most once per 30 seconds */ const STATE_REBUILD_MIN_INTERVAL_MS = 30_000; +export interface PreVerificationOpts { + skipSettleDelay?: boolean; + skipDoctor?: boolean; + skipStateRebuild?: boolean; + skipWorktreeSync?: boolean; +} + export interface PostUnitContext { s: AutoSession; ctx: ExtensionContext; @@ -73,7 +79,7 @@ export interface PostUnitContext { * * Returns "dispatched" if a signal caused stop/pause, "continue" to proceed. */ -export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"dispatched" | "continue"> { +export async function postUnitPreVerification(pctx: PostUnitContext, opts?: PreVerificationOpts): Promise<"dispatched" | "continue"> { const { s, ctx, pi, buildSnapshotOpts, stopAuto, pauseAuto } = pctx; // ── Parallel worker signal check ── @@ -95,8 +101,10 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d // Invalidate all caches invalidateAllCaches(); - // Small delay to let files settle - await new Promise(r => setTimeout(r, 500)); + // Small delay to let files settle (skipped for sidecars where latency matters more) + if (!opts?.skipSettleDelay) { + await new Promise(r => setTimeout(r, 100)); + } // Auto-commit if (s.currentUnit) { @@ -120,8 +128,8 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d keyFiles: summary.frontmatter.key_files?.filter(f => !f.includes("{{")) || undefined, }; } - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "task-summary-parse", error: String(e) }); } } } @@ -131,12 +139,12 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d if (commitMsg) { ctx.ui.notify(`Committed: ${commitMsg.split("\n")[0]}`, "info"); } - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "auto-commit", error: String(e) }); } - // Doctor: fix mechanical bookkeeping - try { + // Doctor: fix mechanical bookkeeping (skipped for lightweight sidecars) + if (!opts?.skipDoctor) try { const scopeParts = s.currentUnit.id.split("/").slice(0, 2); const doctorScope = scopeParts.join("/"); const sliceTerminalUnits = new Set(["complete-slice", "run-uat"]); @@ -168,24 +176,26 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d const reportText = formatDoctorReport(report, { scope: doctorScope, includeWarnings: true }); const structuredIssues = formatDoctorIssuesForPrompt(actionable); dispatchDoctorHeal(pi, doctorScope, reportText, structuredIssues); - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "doctor-heal-dispatch", error: String(e) }); } } } - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "doctor", error: String(e) }); } - // Throttled STATE.md rebuild - const now = Date.now(); - if (now - s.lastStateRebuildAt >= STATE_REBUILD_MIN_INTERVAL_MS) { - try { - await rebuildState(s.basePath); - s.lastStateRebuildAt = now; - autoCommitCurrentBranch(s.basePath, "state-rebuild", s.currentUnit.id); - } catch { - // Non-fatal + // Throttled STATE.md rebuild (skipped for lightweight sidecars) + if (!opts?.skipStateRebuild) { + const now = Date.now(); + if (now - s.lastStateRebuildAt >= STATE_REBUILD_MIN_INTERVAL_MS) { + try { + await rebuildState(s.basePath); + s.lastStateRebuildAt = now; + autoCommitCurrentBranch(s.basePath, "state-rebuild", s.currentUnit.id); + } catch (e) { + debugLog("postUnit", { phase: "state-rebuild", error: String(e) }); + } } } @@ -193,16 +203,16 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d try { const { pruneDeadProcesses } = await import("../bg-shell/process-manager.js"); pruneDeadProcesses(); - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "prune-bg-shell", error: String(e) }); } - // Sync worktree state back to project root - if (s.originalBasePath && s.originalBasePath !== s.basePath) { + // Sync worktree state back to project root (skipped for lightweight sidecars) + if (!opts?.skipWorktreeSync && s.originalBasePath && s.originalBasePath !== s.basePath) { try { syncStateToProjectRoot(s.basePath, s.originalBasePath, s.currentMilestoneId); - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "worktree-sync", error: String(e) }); } } @@ -210,10 +220,10 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d if (s.currentUnit.type === "rewrite-docs") { try { await resolveAllOverrides(s.basePath); - resetRewriteCircuitBreaker(); + s.rewriteAttemptCount = 0; ctx.ui.notify("Override(s) resolved — rewrite-docs completed.", "info"); - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "rewrite-docs-resolve", error: String(e) }); } } @@ -226,8 +236,8 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d const { clearReactiveState } = await import("./reactive-graph.js"); clearReactiveState(s.basePath, mid, sid); } - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "reactive-state-cleanup", error: String(e) }); } } @@ -280,8 +290,8 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d if (triggerArtifactVerified) { invalidateAllCaches(); } - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "artifact-verify", error: String(e) }); } } else { // Hook unit completed — finalize its runtime record @@ -292,8 +302,8 @@ export async function postUnitPreVerification(pctx: PostUnitContext): Promise<"d lastProgressKind: "hook-completed", }); clearUnitRuntimeRecord(s.basePath, s.currentUnit.type, s.currentUnit.id); - } catch { - // Non-fatal + } catch (e) { + debugLog("postUnit", { phase: "hook-finalize", error: String(e) }); } } } @@ -429,8 +439,8 @@ export async function postUnitPostVerification(pctx: PostUnitContext): Promise<" } } } - } catch { - // Triage check failure is non-fatal + } catch (e) { + debugLog("postUnit", { phase: "triage-check", error: String(e) }); } } @@ -475,8 +485,8 @@ export async function postUnitPostVerification(pctx: PostUnitContext): Promise<" ); return "continue"; - } catch { - // Non-fatal — proceed to normal dispatch + } catch (e) { + debugLog("postUnit", { phase: "quick-task-dispatch", error: String(e) }); } } diff --git a/src/resources/extensions/gsd/auto.ts b/src/resources/extensions/gsd/auto.ts index e4e068113..6846bafbd 100644 --- a/src/resources/extensions/gsd/auto.ts +++ b/src/resources/extensions/gsd/auto.ts @@ -622,43 +622,28 @@ export async function stopAuto( if (existsSync(pausedPath)) unlinkSync(pausedPath); } catch { /* non-fatal */ } - s.active = false; - s.paused = false; - s.stepMode = false; - s.unitDispatchCount.clear(); - s.unitRecoveryCount.clear(); - clearInFlightTools(); - s.lastBudgetAlertLevel = 0; - s.lastStateRebuildAt = 0; - s.unitLifetimeDispatches.clear(); - s.currentUnit = null; - s.autoModeStartModel = null; - s.currentMilestoneId = null; - s.originalBasePath = ""; - s.completedUnits = []; - s.pendingQuickTasks = []; - clearSliceProgressCache(); - clearActivityLogState(); - resetProactiveHealing(); - s.pendingCrashRecovery = null; - s.pendingVerificationRetry = null; - s.verificationRetryCount.clear(); - s.pausedSessionFile = null; - ctx?.ui.setStatus("gsd-auto", undefined); - ctx?.ui.setWidget("gsd-progress", undefined); - ctx?.ui.setFooter(undefined); - + // Restore original model before reset() clears the IDs if (pi && ctx && s.originalModelId && s.originalModelProvider) { const original = ctx.modelRegistry.find( s.originalModelProvider, s.originalModelId, ); if (original) await pi.setModel(original); - s.originalModelId = null; - s.originalModelProvider = null; } - s.cmdCtx = null; + // External cleanup (not covered by session reset) + clearInFlightTools(); + clearSliceProgressCache(); + clearActivityLogState(); + resetProactiveHealing(); + + // UI cleanup + ctx?.ui.setStatus("gsd-auto", undefined); + ctx?.ui.setWidget("gsd-progress", undefined); + ctx?.ui.setFooter(undefined); + + // Reset all session state in one call + s.reset(); } /** diff --git a/src/resources/extensions/gsd/auto/session.ts b/src/resources/extensions/gsd/auto/session.ts index e40b87baf..fb234ae26 100644 --- a/src/resources/extensions/gsd/auto/session.ts +++ b/src/resources/extensions/gsd/auto/session.ts @@ -124,6 +124,9 @@ export class AutoSession { // ── Sidecar queue ───────────────────────────────────────────────────── sidecarQueue: SidecarItem[] = []; + // ── Dispatch circuit breakers ────────────────────────────────────── + rewriteAttemptCount = 0; + // ── Metrics ────────────────────────────────────────────────────────────── autoStartTime = 0; lastPromptCharCount: number | undefined; @@ -154,7 +157,7 @@ export class AutoSession { * events between loop iterations. The next runUnit drains this queue * instead of waiting for a new event. */ - pendingAgentEndQueue: Array<{ messages: unknown[] }> = []; + pendingAgentEndQueue: Array<{ messages: unknown[]; unitId?: string }> = []; // ── Methods ────────────────────────────────────────────────────────────── @@ -228,6 +231,7 @@ export class AutoSession { this.lastBaselineCharCount = undefined; this.pendingQuickTasks = []; this.sidecarQueue = []; + this.rewriteAttemptCount = 0; // Signal handler this.sigtermHandler = null;