From a97aa84a205ad7b0f8a4bce6b572eaad78af0fbd Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Sun, 23 Aug 2026 15:05:27 -0700 Subject: [PATCH] fix: remove debug probes swept into ab9789f0a8 by mistake MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ab9789f0a8 was committed with `git add -A` while an agent was mid-investigation in this same checkout, so it captured that agent's temporary instrumentation: eight `process.stderr.write('[F] …')` probe lines inside product code (executor/mark-stuck-aborted.ts) and a 359-line scratch copy of a test file. Both were pushed. Reverting both; no product behavior was ever intended to change in those files. Also lands the executor-stuck-requeue fix that investigation produced: the grace-timeout assertion ran before the product finished, because the callback continues past its timer into resetStepsIfWorkLost -> loadWorkspaceConfig, real async fs I/O that `vi.advanceTimersByTimeAsync` does not await. The test now awaits a completion barrier resolved by the requeue's own final moveTask rather than a timeout or retry. The product was correct. Lesson for this checkout: stage by explicit path while agents are running. Co-Authored-By: Claude Opus 5 --- ...or-stuck-requeue-preserve-progress.test.ts | 19 + .../src/__tests__/zz-probe-stuck.test.ts | 359 ------------------ .../engine/src/executor/mark-stuck-aborted.ts | 8 - 3 files changed, 19 insertions(+), 367 deletions(-) delete mode 100644 packages/engine/src/__tests__/zz-probe-stuck.test.ts diff --git a/packages/engine/src/__tests__/executor-stuck-requeue-preserve-progress.test.ts b/packages/engine/src/__tests__/executor-stuck-requeue-preserve-progress.test.ts index 4c23902c97..0db1dee698 100644 --- a/packages/engine/src/__tests__/executor-stuck-requeue-preserve-progress.test.ts +++ b/packages/engine/src/__tests__/executor-stuck-requeue-preserve-progress.test.ts @@ -333,6 +333,24 @@ describe("TaskExecutor stuck requeue preserve-progress reconciliation", () => { vi.useFakeTimers(); const task = createTask(); const store = createMutableStore(task); + /* + FNXC:StuckRequeue 2026-08-23-22:35: + A completion BARRIER, not a wait-and-hope. The grace-timeout callback is async past its timer: + `resetStepsIfWorkLost` awaits `loadWorkspaceConfig(rootDir)`, which is REAL async fs I/O, and + `vi.advanceTimersByTimeAsync` only drains timers and microtasks — it returns while that I/O leg + is still outstanding. Asserting straight after the advance therefore read the graph's + `step 0 = in-progress` before the reconciliation's reset landed (deterministic in isolation; + order-dependent, and observed flaking, in a whole-file run). The product is correct: the reset, + the currentStep clear, and the requeue all happen, in that order, and the requeue move is LAST. + Awaiting it is the exact, poll-free point at which every assertion below is observable. + */ + const forceRequeued = new Promise((resolve) => { + store.moveTask.mockImplementation(async (_taskId: string, column: Task["column"], options?: { preserveProgress?: boolean }) => { + task.column = column; + if (column === "todo" && options?.preserveProgress) resolve(); + return task; + }); + }); let releasePrompt!: () => void; const promptRelease = new Promise((resolve) => { releasePrompt = resolve; @@ -344,6 +362,7 @@ describe("TaskExecutor stuck requeue preserve-progress reconciliation", () => { await startedPromise; executor.markStuckAborted(task.id, true); await vi.advanceTimersByTimeAsync(60_000); + await forceRequeued; expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); expect(task.currentStep).toBe(0); diff --git a/packages/engine/src/__tests__/zz-probe-stuck.test.ts b/packages/engine/src/__tests__/zz-probe-stuck.test.ts deleted file mode 100644 index 240c1e70ef..0000000000 --- a/packages/engine/src/__tests__/zz-probe-stuck.test.ts +++ /dev/null @@ -1,359 +0,0 @@ -import { beforeEach, describe, expect, it, vi } from "vitest"; -import "./executor-test-helpers.js"; -import type { Task } from "@fusion/core"; -import { TaskExecutor } from "../executor.js"; -import { removeWorktree } from "../worktree/worktree-pool.js"; -import { - createMockStore, - mockCleanup, - mockExecuteAll, - mockedCreateFnAgent, - mockedDescribeRegisteredWorktrees, - mockedExecSync, - resetExecutorMocks, -} from "./executor-test-helpers.js"; - -const mockedRemoveWorktree = vi.mocked(removeWorktree); - -/* -FNXC:EngineTests 2026-07-19-16:05 (U10b): -Requirement under test is unchanged: a force-requeue with preserveProgress must never leave the -board claiming work that the discarded worktree took with it. What changed is WHO owns the step -list. Under the workflow graph the `parse-steps` node re-materializes `task.steps` from PROMPT.md -at the start of every run, so the executor's step statuses at abort time are the graph's, not a -hand-seeded fixture. The fixture prompt therefore has to BE the step source (see -`createMutableStore`'s `getTaskDocument`), and the assertions read the materialized list. -*/ -const STEP_PROMPT = - "# test\n## Steps\n### Step 0: Preflight\n- [ ] check\n### Step 1: Implement\n- [ ] code\n### Step 2: Verify\n- [ ] verify"; - -/* -FNXC:EngineTests 2026-07-19-16:05 (U10b): -The graph drives its own step transitions through the same `updateStep` seam, tagged -`{ source: "graph" }`. The lost-work reconciliation (`resetStepsIfWorkLost`) writes untagged. Split -them so "reset exactly the steps whose work was lost" stays measurable now that the graph shares -the seam — a bare call count would measure the graph, not the reconciliation. -*/ -function reconciliationStepResets(store: { updateStep: { mock: { calls: unknown[][] } } }): unknown[][] { - return store.updateStep.mock.calls.filter((call) => call[3] === undefined); -} - -function createTask(overrides: Partial = {}): Task { - return { - id: "FN-7174", - title: "Preserve stuck progress", - description: STEP_PROMPT, - prompt: STEP_PROMPT, - column: "in-progress", - dependencies: [], - steps: [ - { name: "Step 0", status: "done" }, - { name: "Step 1", status: "in-progress" }, - { name: "Step 2", status: "pending" }, - ], - currentStep: 2, - log: [], - createdAt: new Date().toISOString(), - updatedAt: new Date().toISOString(), - worktree: "/tmp/test/.worktrees/fn-7174-worktree", - branch: "fusion/fn-7174", - baseCommitSha: "base-sha", - enabledWorkflowSteps: [], - ...overrides, - }; -} - -function installGitResult(kind: "uncommitted-only" | "committed") { - mockedExecSync.mockImplementation((cmd: string) => { - if (cmd.includes("git rev-parse --is-inside-work-tree")) return "true\n"; - if (cmd.includes("git merge-base")) return "base-sha\n"; - if (cmd.includes("git rev-parse")) { - return kind === "uncommitted-only" ? "base-sha\n" : "branch-sha\n"; - } - return ""; - }); -} - -/* -FNXC:StuckRequeue 2026-08-02-00:20: -The branch-durability PROOF in resetStepsIfWorkLost runs `git merge-base "" HEAD`; only -THAT proof must fail for this scenario. Setup's contamination/diff base uses `git merge-base HEAD main` -(and origin/main), which must still resolve — otherwise execution short-circuits before the agent -session ever starts and the stuck-requeue cleanup under test is never reached (the test then hangs on -startedPromise). Scope the failure to the task-branch merge-base and leave the main-base lookups intact. -*/ -function installGitProofFailure() { - mockedExecSync.mockImplementation((cmd: string) => { - if (cmd.includes("git rev-parse --is-inside-work-tree")) return "true\n"; - // Branch-durability PROOF (resetStepsIfWorkLost): `git merge-base "" HEAD`. - // Only this proof fails; every setup lookup mirrors the uncommitted-only fixture so execution - // still reaches the running session before the stuck kill. - if (cmd.includes("git merge-base") && cmd.includes("fusion/missing-fn-7174")) { - throw new Error("fatal: not a valid object name fusion/missing-fn-7174"); - } - if (cmd.includes("git merge-base")) return "base-sha\n"; - if (cmd.includes("git rev-parse")) return "base-sha\n"; - return ""; - }); -} - -function createMutableStore(task: Task, settings: Record = {}) { - const store = createMockStore(); - store.getSettings.mockResolvedValue({ - maxConcurrent: 2, - maxWorktrees: 4, - pollIntervalMs: 15000, - groupOverlappingFiles: false, - autoMerge: false, - ...settings, - }); - store.getTask.mockImplementation(async () => task); - /* - FNXC:EngineTests 2026-07-19-16:05 (U10b): - Point the graph's PROMPT.md artifact read at this fixture's own prompt so the materialized step - list is the three steps this file reasons about, instead of the shared harness's single-step - default. - */ - store.getTaskDocument.mockImplementation(async (_id: string, key: string) => - key === "PROMPT.md" ? { content: task.prompt } : undefined, - ); - store.updateStep.mockImplementation(async function (this: unknown, _taskId: string, stepIndex: number, status: Task["steps"][number]["status"]) { - process.stderr.write(`[STEP] ${stepIndex} -> ${status} src=${JSON.stringify(arguments[3])}\n`); - task.steps[stepIndex].status = status; - return task; - }); - store.updateTask.mockImplementation(async (_taskId: string, updates: Partial) => { - if (updates.steps || updates.currentStep !== undefined) process.stderr.write(`[UPD] ${JSON.stringify({steps:updates.steps?.map(s=>s.status), currentStep: updates.currentStep})}\n`); - Object.assign(task, updates); - return task; - }); - store.moveTask.mockImplementation(async (_taskId: string, column: Task["column"]) => { - task.column = column; - return task; - }); - return store; -} - -function installSingleSession(resolvePrompt: () => Promise | void = async () => {}) { - let started!: () => void; - const startedPromise = new Promise((resolve) => { - started = resolve; - }); - const session = { - prompt: vi.fn().mockImplementation(async () => { - started(); - await resolvePrompt(); - }), - dispose: vi.fn(), - subscribe: vi.fn(), - on: vi.fn(), - setThinkingLevel: vi.fn(), - sessionManager: { getLeafId: vi.fn().mockReturnValue("leaf-1") }, - getSessionStats: vi.fn().mockReturnValue({ tokens: {} }), - }; - mockedCreateFnAgent.mockResolvedValue({ session, sessionFile: "/tmp/session.json" } as any); - return { session, startedPromise }; -} - -/* -FNXC:EngineTests 2026-07-19-16:05 (U10b): -`beforeAbort` runs after the agent session exists but before the stuck kill, which is the only -window where a test can stage state the graph has already written past — the graph's own column -boundary move and its step-0 in-progress transition both land before the kill. Simulating a -concurrent recovery or a no-work session by pre-seeding the fixture no longer works. -*/ -async function runSingleSessionStuckRequeue( - task: Task, - settings: Record = {}, - beforeAbort?: (live: Task) => void, -) { - const store = createMutableStore(task, settings); - let releasePrompt!: () => void; - const promptRelease = new Promise((resolve) => { - releasePrompt = resolve; - }); - const { startedPromise } = installSingleSession(() => promptRelease); - const executor = new TaskExecutor(store as any, "/tmp/test", {}); - - const executePromise = executor.execute(task); - await startedPromise; - beforeAbort?.(task); - executor.markStuckAborted(task.id, true); - releasePrompt(); - await executePromise; - return { store, executor }; -} - -async function runStepSessionStuckRequeue(task: Task, settings: Record = {}) { - const store = createMutableStore(task, { - runStepsInNewSessions: true, - maxParallelSteps: 2, - ...settings, - }); - let release!: () => void; - mockExecuteAll.mockReturnValue(new Promise((resolve) => { - release = resolve; - })); - const executor = new TaskExecutor(store as any, "/tmp/test", {}); - - const executePromise = executor.execute(task); - await vi.waitFor(() => expect((executor as any).activeStepExecutors.has(task.id)).toBe(true)); - executor.markStuckAborted(task.id, true); - release(); - await executePromise; - return { store, executor }; -} - -describe.only("TaskExecutor stuck requeue preserve-progress reconciliation", () => { - beforeEach(() => { - resetExecutorMocks(); - mockedRemoveWorktree.mockResolvedValue(undefined as any); - mockedDescribeRegisteredWorktrees.mockResolvedValue({ - rawOutput: "worktree /tmp/test/.worktrees/fn-7174-worktree\nbranch refs/heads/fusion/fn-7174\n", - canonicalized: ["/tmp/test/.worktrees/fn-7174-worktree"], - }); - mockCleanup.mockResolvedValue(undefined); - installGitResult("uncommitted-only"); - }); - - it("reproduces the default preserve-progress corruption case and resets uncommitted-only steps before removing the worktree", async () => { - const task = createTask(); - const { store } = await runSingleSessionStuckRequeue(task); - - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(task.currentStep).toBe(0); - // Every step the discarded worktree was mid-way through is reset — here the graph's step 0. - expect(reconciliationStepResets(store)).toEqual([[task.id, 0, "pending"]]); - expect(mockedRemoveWorktree).toHaveBeenCalledWith(expect.objectContaining({ - worktreePath: "/tmp/test/.worktrees/fn-7174-worktree", - taskId: task.id, - expectedOwnerTaskId: task.id, - })); - expect(store.updateTask).toHaveBeenCalledWith(task.id, expect.objectContaining({ - worktree: null, - branch: null, - })); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - }); - - it("resets steps when git cannot prove a stale branch has durable commits before cleanup", async () => { - installGitProofFailure(); - const task = createTask({ branch: "fusion/missing-fn-7174" }); - const { store } = await runSingleSessionStuckRequeue(task); - - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(task.currentStep).toBe(0); - expect(reconciliationStepResets(store)).toEqual([[task.id, 0, "pending"]]); - expect(mockedRemoveWorktree).toHaveBeenCalled(); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - }); - - it("keeps committed step progress unchanged on preserve-progress stuck requeue", async () => { - installGitResult("committed"); - const task = createTask(); - const { store } = await runSingleSessionStuckRequeue(task); - - // Committed work is durable: the graph's in-flight step keeps its status and currentStep stands. - expect(task.steps.map((step) => step.status)).toEqual(["in-progress", "pending", "pending"]); - expect(task.currentStep).toBe(2); - expect(reconciliationStepResets(store)).toEqual([]); - expect(mockedRemoveWorktree).toHaveBeenCalled(); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - }); - - it("keeps preserveProgress=false reset behavior while moving without preserve options", async () => { - const task = createTask(); - const { store } = await runSingleSessionStuckRequeue(task, { preserveProgressOnStuckRequeue: false }); - - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(task.currentStep).toBe(0); - expect(reconciliationStepResets(store)).toEqual([[task.id, 0, "pending"]]); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", undefined); - }); - - /* - FNXC:EngineTests 2026-07-19-16:05 (U10b): - A session that recorded no step progress must not be "reconciled" at all — there is nothing to - lose, so the requeue writes no step statuses. Post-cutover the all-pending state has to be staged - at kill time (the graph marks its first step in-progress before the session starts), so the - no-work condition is asserted against the reconciliation's own writes rather than the seam's. - */ - it("does nothing for no-work tasks with no completed or in-progress steps", async () => { - const task = createTask(); - const { store } = await runSingleSessionStuckRequeue(task, {}, (live) => { - for (const step of live.steps) step.status = "pending"; - }); - - expect(reconciliationStepResets(store)).toEqual([]); - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - }); - - /* - FNXC:EngineTests 2026-07-19-16:05 (U10b): - The guard is the reason this file exists: if a concurrent recovery has already carried the task - past in-progress/todo, the stuck requeue must abandon its cleanup rather than destroy the - worktree that recovery now depends on and clobber the card back to todo. The graph moves the card - itself during the run, so the concurrent recovery is now staged at kill time via `beforeAbort` - instead of by seeding `column` before `execute()`. - - FNXC:EngineTests 2026-07-19-16:05 (U10b): - "Never moved to todo" is no longer the guard's contract — the graph, as a separate authority, - rebounds its own failed run for execution resume (`{ moveSource: "engine", recoveryRehome: true }`) - and that move is not destructive. What the guard must suppress is the stuck-requeue's own - bare-`{preserveProgress:true}` move plus the cleanup that goes with it: step resets, worktree - removal, and the worktree/branch clear. - */ - it("preserves the concurrent-recovery guard without removing worktree or clearing the checkout", async () => { - const task = createTask(); - const { store } = await runSingleSessionStuckRequeue(task, {}, (live) => { - live.column = "in-review"; - }); - - expect(reconciliationStepResets(store)).toEqual([]); - expect(mockedRemoveWorktree).not.toHaveBeenCalled(); - expect(store.updateTask).not.toHaveBeenCalledWith(task.id, expect.objectContaining({ - worktree: null, - branch: null, - })); - expect(store.moveTask).not.toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - expect(store.moveTask).not.toHaveBeenCalledWith(task.id, "todo"); - }); - - it("applies the same lost-work reconciliation to the step-session requeue path", async () => { - const task = createTask(); - const { store } = await runStepSessionStuckRequeue(task); - - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(task.currentStep).toBe(0); - expect(reconciliationStepResets(store)).toEqual([[task.id, 0, "pending"]]); - expect(mockedRemoveWorktree).toHaveBeenCalled(); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - }); - - it("applies the same lost-work reconciliation to the force-requeue grace-timeout path", async () => { - vi.useFakeTimers(); - const task = createTask(); - const store = createMutableStore(task); - let releasePrompt!: () => void; - const promptRelease = new Promise((resolve) => { - releasePrompt = resolve; - }); - const { startedPromise } = installSingleSession(() => promptRelease); - const executor = new TaskExecutor(store as any, "/tmp/test", {}); - - const executePromise = executor.execute(task); - await startedPromise; - executor.markStuckAborted(task.id, true); - await vi.advanceTimersByTimeAsync(60_000); - process.stderr.write(`[ASSERT] ${JSON.stringify(task.steps.map(s=>s.status))}\n`); - - expect(task.steps.map((step) => step.status)).toEqual(["pending", "pending", "pending"]); - expect(task.currentStep).toBe(0); - expect(mockedRemoveWorktree).toHaveBeenCalled(); - expect(store.moveTask).toHaveBeenCalledWith(task.id, "todo", { preserveProgress: true }); - - releasePrompt(); - await executePromise; - }); -}); diff --git a/packages/engine/src/executor/mark-stuck-aborted.ts b/packages/engine/src/executor/mark-stuck-aborted.ts index 1d40ed8d3c..78c9d1e69a 100644 --- a/packages/engine/src/executor/mark-stuck-aborted.ts +++ b/packages/engine/src/executor/mark-stuck-aborted.ts @@ -56,14 +56,12 @@ export function markStuckAborted( if (shouldRequeue && deps.executing.has(taskId)) { const FORCE_REQUEUE_GRACE_MS = 60_000; // 60 s — generous, but bounded setTimeout(async () => { - process.stderr.write('[F] timer fired\n'); if (!deps.executing.has(taskId)) return; // executor unwound normally — nothing to do // Re-check the latest column: self-healing may have already moved the // task out of in-progress (e.g. recoverCompletedTasks → in-review). // Force-requeueing in that case would clobber a valid recovery, undo // the worktree/branch state that recovery now relies on, and reset // step progress. - process.stderr.write('[F] pre-getTask\n'); let latestColumn: string | undefined; try { const latestTask = await deps.store.getTask(taskId); @@ -89,7 +87,6 @@ export function markStuckAborted( `(likely a hung subprocess) — force-requeueing`, ); try { - process.stderr.write('[F] pre-settings\n'); const settings = await deps.store.getSettings(); const preserveProgress = settings.preserveProgressOnStuckRequeue !== false; const latestTask = await deps.store.getTask(taskId); @@ -125,13 +122,10 @@ export function markStuckAborted( // Spawned children must be terminated before the canonical reaper clears // spawnedAgents bookkeeping; otherwise child agent sessions would be orphaned. - process.stderr.write('[F] pre-terminateChildren\n'); await deps.terminateAllChildren(taskId).catch((err: unknown) => { executorLog.warn(`${taskId}: spawned child cleanup failed during force-requeue: ${err instanceof Error ? err.message : String(err)}`); }); - process.stderr.write('[F] pre-abortInFlight\n'); await deps.awaitAbortInFlightTaskWork(taskId, "force-requeue after stuck-kill unwind timeout"); - process.stderr.write('[F] post-abortInFlight\n'); // awaitAbortInFlightTaskWork marks pausedAborted as a generic abort // signal (KB-PROV 2026-07-26: `engine-abort`, since the force-requeue is // engine-initiated and passes no `userCanceled`). @@ -144,9 +138,7 @@ export function markStuckAborted( The force path mirrors normal stuck-requeue cleanup: before reaping a hung executor's worktree, reconcile step progress against committed branch state so preserved progress never points at deleted uncommitted work. */ if (!externalExecutionRoute.configured) { - process.stderr.write('[F] pre-reset\n'); await deps.resetStepsIfWorkLost(latestTask); - process.stderr.write('[F] post-reset\n'); } let cleanupFailed = false;