root/fusion
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(core): seed the prompt for quick-add Start creates; instrument hold-release

Browse Source 
Quick-add "Start" collapses create+promote into one request: it submits the
workflow id AND the post-intake `todo` column together, so the card lands in
`todo` having never sat in the workflow's manual intake column. The intake test
in task-creation.ts only matched `triage` or the resolved intake column, so the
card got generateSpecifiedPrompt — whose hard-coded boilerplate steps
("Implement the required changes") no planner ever wrote.

That stranded the card permanently: triage's todo-discovery admits a card only
when its PROMPT.md reads as a seed, so the placeholder spec was classified
"already planned" and never planned, while nothing could execute it either
(steps: []). It sat in Todo forever with no log line in any lane. Observed on
FN-8587.

Creates into `todo` on a manual-intake workflow (resolved intake is not the
legacy `triage`) now get the bootstrap seed. The pinned contract for a plain
direct create into todo on the default workflow — which intentionally keeps
generateSpecifiedPrompt — is untouched, and both create sites are fixed in step.

Also instrument the hold/release sweep, which had reasons but no timings:
per-task held duration reported on release, a per-sweep summary breaking out the
prefetch cost (a sequential await per non-archived task, so it scales with board
size rather than with held cards), and a warn when a sweep exceeds 2s — so a
"ready card doesn't move" delay can be attributed between poll cadence, sweep
cost, and a card genuinely queued on capacity.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
gsxdsm
2026-07-25 09:52:18 -07:00
parent e712b6faea
commit 10df734bd1
5 changed files with 358 additions and 2 deletions
Download Patch File Download Diff File Expand all files Collapse all files

7
.changeset/quick-add-start-seeds-prompt.md Normal file
View File

@@ -0,0 +1,7 @@
---
"@runfusion/fusion": patch
---
summary: Fix quick-add Start creating tasks that could never be planned, and log how long held cards wait.
category: fix
dev: Quick-add "Start" submits a workflow id and the post-intake `todo` column in one request, so the card missed the intake branch in `task-creation.ts` and got `generateSpecifiedPrompt`'s hard-coded placeholder steps. Triage then read the non-seed PROMPT.md as "already planned" and never planned it, stranding the card in Todo with no log line (observed on FN-8587). Creates into `todo` on a manual-intake workflow (resolved intake != `triage`) now get the bootstrap seed; the pinned default-workflow direct-create-into-todo contract is unchanged. Separately, `runHoldReleaseSweep` now logs per-task held duration on release, a per-sweep summary with the prefetch cost broken out (the prefetch is a sequential await per non-archived task, so it scales with board size), and warns when a sweep exceeds 2s.

36
packages/core/src/__tests__/store-create-intake-column.test.ts
View File

@@ -84,6 +84,42 @@ pgTest("createTask intake-column wiring (Coding (Ideas))", () => {
expect(prompt).toBe(`# ${task.id}\n\n${task.description}\n`);
});
/*
FNXC:CodingIdeasWorkflow 2026-07-25-14:20:
Regression for the stranded quick-add "Start" card (FN-8587). Start collapses create+promote into
one request — workflow id AND the post-intake `todo` column together — so the card never sits in
the manual intake column. It got generateSpecifiedPrompt, whose hard-coded boilerplate steps
("Implement the required changes") no planner ever wrote. Triage then classified the non-seed
PROMPT.md as "already planned" and never planned it, so the card sat in Todo permanently with no
log line in any lane.
Surface enumeration (invariant: an unplanned card gets the seed no matter which column of a
manual-intake workflow it is created into, while pre-specified creates keep their spec):
- Create into the intake column itself (covered above) -> seed.
- Create straight into todo on a manual-intake workflow (this case, the Start path) -> seed.
- Promote intake -> todo via moveTask (covered below) -> seed preserved.
- Default-workflow direct create into todo -> still generateSpecifiedPrompt (next test).
- An explicit promptOverride always wins over all of the above.
*/
it("writes a bootstrap PROMPT.md for a quick-add Start create landing straight in todo", async () => {
const store = h.store();
const task = await store.createTask({
description: "quick add start task",
workflowId: "builtin:coding-ideas",
column: "todo",
});
expect(task.column).toBe("todo");
const prompt = await readFile(
join(h.rootDir(), ".fusion", "tasks", task.id, "PROMPT.md"),
"utf-8",
);
expect(prompt).toBe(buildBootstrapPrompt(task.id, task.title, task.description));
// The placeholder-spec boilerplate that stranded FN-8587 must not appear.
expect(prompt).not.toContain("Implement the required changes");
expect(prompt).not.toContain("## Steps");
});
it("keeps generateSpecifiedPrompt for a direct create into todo (not bootstrap)", async () => {
const store = h.store();
const task = await store.createTask({ description: "direct todo create", column: "todo" });

36
packages/core/src/task-store/task-creation.ts
View File

@@ -430,8 +430,30 @@ export async function _createTaskInternalBackendImpl(store: TaskStore, input: Ta
workflow's resolved manual intake (e.g. Coding (Ideas) → "ideas"). Direct
creates into other columns keep generateSpecifiedPrompt (main parity).
*/
/*
FNXC:CodingIdeasWorkflow 2026-07-25-14:20:
Quick-add "Start" collapses create+promote into ONE request: it submits the workflow id AND
the post-intake destination column together, so the card lands in `todo` having never sat in
the workflow's manual intake column. It is still UNPLANNED — nothing has written a spec — but
the intake test above only matched `triage` or the resolved intake column, so the card got
`generateSpecifiedPrompt` instead of the bootstrap seed.
That stranded the card permanently: triage's todo-discovery admits a card only when its
PROMPT.md reads as a seed, so a placeholder spec is classified "already planned" and never
planned, while `generateSpecifiedPrompt` emits hard-coded boilerplate steps ("Implement the
required changes") that no planner ever produced. The card sat in Todo forever with no log
line in any lane. Observed on FN-8587.
Guarded to manual-intake workflows (resolved intake is not the legacy `triage`) landing in the
plan-in-place `todo` column, so the pinned contract for a plain direct create into todo on the
default workflow — which intentionally keeps generateSpecifiedPrompt — is untouched.
*/
const isUnplannedStartCreate = options?.resolvedEntryColumn !== undefined
&& options.resolvedEntryColumn !== "triage"
&& task.column === "todo";
const isIntakeColumn = task.column === "triage"
|| (options?.resolvedEntryColumn !== undefined && task.column === options.resolvedEntryColumn);
|| (options?.resolvedEntryColumn !== undefined && task.column === options.resolvedEntryColumn)
|| isUnplannedStartCreate;
const usedBootstrapPrompt = !options?.promptOverride && isIntakeColumn;
const prompt = options?.promptOverride
?? (isIntakeColumn
@@ -1053,8 +1075,18 @@ export async function _createTaskInternalImpl(store: TaskStore, input: TaskCreat
workflow's resolved manual intake (e.g. Coding (Ideas) → "ideas"). Direct
creates into other columns keep generateSpecifiedPrompt (main parity).
*/
/*
FNXC:CodingIdeasWorkflow 2026-07-25-14:20:
Mirror of the backend path above — quick-add "Start" submits workflow id + post-intake column in
one request, so the card is unplanned despite not landing in the intake column. See the fuller
rationale there; keeping both copies in step is the whole point (this pair has drifted before).
*/
const isUnplannedStartCreate = options?.resolvedEntryColumn !== undefined
&& options.resolvedEntryColumn !== "triage"
&& task.column === "todo";
const isIntakeColumn = task.column === "triage"
|| (options?.resolvedEntryColumn !== undefined && task.column === options.resolvedEntryColumn);
|| (options?.resolvedEntryColumn !== undefined && task.column === options.resolvedEntryColumn)
|| isUnplannedStartCreate;
const usedBootstrapPrompt = !options?.promptOverride && isIntakeColumn;
const prompt = options?.promptOverride
?? (isIntakeColumn

193
packages/engine/src/__tests__/hold-release-instrumentation.test.ts Normal file
View File

@@ -0,0 +1,193 @@
/*
FNXC:HoldReleaseInstrumentation 2026-07-25-14:35:
Operator-reported symptom: "tasks that finish planning and are ready don't move immediately — there
is a long delay." The sweep logged per-task hold REASONS but never how LONG a card waited or how
long the sweep itself took, so the delay could not be attributed between the poll cadence, sweep
execution cost, and a card legitimately queued on capacity.
These tests pin the instrumentation's OBSERVABLE contract (what an operator reading the log can
conclude), not its exact wording:
- a released card reports the elapsed held time, measured from when it was first held;
- the wait accumulates across sweeps while the reason is unchanged, and the clock is keyed by
reason so a reason change restarts it rather than conflating two different waits;
- a slow sweep is reported at warn level, because then the sweep IS the delay;
- a quiet sweep does not reprint at info level every poll (that is why hold logging was demoted
to debug once before — a full board buried real scheduler events);
- bookkeeping for a no-longer-held task is dropped, so the map cannot grow without bound.
*/
import { beforeEach, describe, expect, it, vi } from "vitest";
import type { Task, TaskStore, WorkflowIr } from "@fusion/core";
import { runHoldReleaseSweep, resetHoldReleaseInstrumentation } from "../hold-release.js";
import { schedulerLog } from "../logger.js";
const WF = "custom:wf";
function task(over: Partial<Task> = {}): Task {
return {
id: "FN-1",
title: "t",
description: "",
column: "todo",
status: null,
dependencies: [],
steps: [],
currentStep: 0,
log: [],
createdAt: "2026-01-01T00:00:00.000Z",
updatedAt: "2026-01-01T00:00:00.000Z",
columnMovedAt: "2026-01-01T00:00:00.000Z",
...over,
} as Task;
}
/** Single wip column with a capacity hold on todo — the Coding (Ideas) shape. */
function singleWipIr(): WorkflowIr {
return {
version: "v2",
id: WF,
nodes: [],
edges: [],
columns: [
{ id: "todo", label: "Todo", traits: [{ trait: "hold", config: { release: "capacity" } }] },
{
id: "in-progress",
label: "In Progress",
traits: [{ trait: "wip", config: { limitSetting: "maxConcurrent" } }],
},
{ id: "done", label: "Done", traits: [{ trait: "complete" }] },
],
} as unknown as WorkflowIr;
}
function storeWith(tasks: Task[], ir: WorkflowIr, settings: Record<string, unknown>): TaskStore {
const selection = { workflowId: WF, stepIds: [] };
return {
getSettings: vi.fn(async () => settings),
listTasks: vi.fn(async () => tasks),
moveTaskIf: vi.fn(async (id: string, column: string) => {
const cur = tasks.find((t) => t.id === id)!;
cur.column = column;
return { task: cur, moved: true };
}),
logEntry: vi.fn(async () => undefined),
recordRunAuditEvent: vi.fn(async () => undefined),
getCompletionHandoffAcceptedMarker: vi.fn(async () => null),
getTaskWorkflowSelection: vi.fn(() => selection),
getTaskWorkflowSelectionAsync: vi.fn(async () => selection),
getWorkflowDefinition: vi.fn(async () => ({ ir })),
} as unknown as TaskStore;
}
/** A controllable clock so held durations are exact, never wall-clock flaky. */
function clock(startMs = 1_000_000) {
let t = startMs;
return { now: () => t, advance: (ms: number) => { t += ms; } };
}
describe("hold/release sweep instrumentation", () => {
beforeEach(() => {
resetHoldReleaseInstrumentation();
vi.restoreAllMocks();
});
it("reports how long a card was held when it is finally released", async () => {
const log = vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
const held = task({ id: "H", column: "todo" });
const occupant = task({ id: "O", column: "in-progress" });
const store = storeWith([held, occupant], singleWipIr(), { maxConcurrent: 1 });
const c = clock();
// Saturated: the card is held and the clock starts.
const first = await runHoldReleaseSweep(store, { now: c.now });
expect(first.released).toEqual([]);
expect(first.held.some((h) => h.taskId === "H" && h.reason === "downstream-full")).toBe(true);
c.advance(45_000);
occupant.column = "done";
const second = await runHoldReleaseSweep(store, { now: c.now });
expect(second.released).toEqual(["H"]);
// The release line carries the measured wait — the number that explains the delay.
const releaseLine = log.mock.calls.map((c2) => String(c2[0])).find((l) => l.includes("Hold release for H"));
expect(releaseLine).toBeDefined();
expect(releaseLine).toContain("45000ms");
});
it("accumulates the wait across sweeps while the hold reason is unchanged", async () => {
const log = vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
const held = task({ id: "H", column: "todo", dependencies: ["FN-DEP"] });
const occupant = task({ id: "O", column: "in-progress" });
const ir = singleWipIr();
const store = storeWith([held, occupant], ir, { maxConcurrent: 1 });
const c = clock();
await runHoldReleaseSweep(store, { now: c.now }); // held: downstream-full
c.advance(60_000);
// Free the slot so the reason changes on the next pass, then release.
occupant.column = "done";
c.advance(5_000);
const released = await runHoldReleaseSweep(store, { now: c.now });
expect(released.released).toEqual(["H"]);
const releaseLine = log.mock.calls.map((x) => String(x[0])).find((l) => l.includes("Hold release for H"));
// Total wait under the SAME reason is reported (65s), not a reset-to-zero.
expect(releaseLine).toContain("65000ms");
});
it("warns when the sweep itself is slow, since then the sweep is the delay", async () => {
const warn = vi.spyOn(schedulerLog, "warn").mockImplementation(() => {});
vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
vi.spyOn(schedulerLog, "debug").mockImplementation(() => {});
const store = storeWith([task({ id: "H", column: "todo" })], singleWipIr(), { maxConcurrent: 5 });
// A clock that jumps 3s across the sweep simulates a slow pass deterministically.
let calls = 0;
const now = () => { calls += 1; return 1_000_000 + (calls > 1 ? 3_000 : 0); };
await runHoldReleaseSweep(store, { now });
const warnLine = warn.mock.calls.map((c) => String(c[0])).find((l) => l.includes("Hold-release sweep"));
expect(warnLine).toBeDefined();
expect(warnLine).toMatch(/sweep exceeded/);
// The prefetch cost is broken out so an O(board-size) prefetch is attributable.
expect(warnLine).toContain("prefetch");
});
it("keeps a quiet sweep at debug so a full board does not bury real scheduler events", async () => {
const log = vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
const debug = vi.spyOn(schedulerLog, "debug").mockImplementation(() => {});
const held = task({ id: "H", column: "todo" });
const occupant = task({ id: "O", column: "in-progress" });
const store = storeWith([held, occupant], singleWipIr(), { maxConcurrent: 1 });
const c = clock();
await runHoldReleaseSweep(store, { now: c.now }); // nothing released
expect(debug.mock.calls.some((x) => String(x[0]).includes("Hold-release sweep"))).toBe(true);
expect(log.mock.calls.some((x) => String(x[0]).includes("Hold-release sweep"))).toBe(false);
});
it("drops bookkeeping for a task that is no longer held", async () => {
vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
vi.spyOn(schedulerLog, "debug").mockImplementation(() => {});
const held = task({ id: "H", column: "todo" });
const occupant = task({ id: "O", column: "in-progress" });
const store = storeWith([held, occupant], singleWipIr(), { maxConcurrent: 1 });
const c = clock();
await runHoldReleaseSweep(store, { now: c.now });
c.advance(10_000);
occupant.column = "done";
await runHoldReleaseSweep(store, { now: c.now });
// Released, so the next sweep must not re-report a stale accumulated wait.
const log2 = vi.spyOn(schedulerLog, "log").mockImplementation(() => {});
c.advance(10_000);
held.column = "todo";
await runHoldReleaseSweep(store, { now: c.now });
const line = log2.mock.calls.map((x) => String(x[0])).find((l) => l.includes("Hold release for H"));
if (line) expect(line).toContain("0ms");
});
});

88
packages/engine/src/hold-release.ts
View File

@@ -402,11 +402,44 @@ function countCapacitySlot(
/**
* Run one hold/release sweep pass for the default workflow-column runtime.
*/
/*
FNXC:HoldReleaseInstrumentation 2026-07-25-14:35:
Operator-reported symptom: "tasks that finish planning and are ready don't move immediately — there
is a long delay." The sweep already logged per-task hold REASONS, but nothing recorded how LONG a
card waited or how long the sweep itself took, so the delay could not be attributed between (a) the
poll cadence, (b) sweep execution cost, and (c) a card legitimately waiting on capacity.
`heldSince` records when each task was first observed held with its current reason. On release the
elapsed time is logged; the entry is dropped when the task releases or stops being held, so the map
tracks only currently-held cards and cannot grow without bound. Reason changes reset the clock, so
"waiting 4m on downstream-full" is never conflated with "waiting 4m on deps-unsatisfied".
*/
const heldSince = new Map<string, { reason: string; sinceMs: number }>();
/** Sweeps slower than this are the delay rather than a symptom of it — log loudly. */
const SLOW_SWEEP_WARN_MS = 2_000;
/** Record/refresh the held-since clock for a task and return how long it has been held. */
function trackHeld(taskId: string, reason: string, nowMs: number): number {
const existing = heldSince.get(taskId);
if (!existing || existing.reason !== reason) {
heldSince.set(taskId, { reason, sinceMs: nowMs });
return 0;
}
return nowMs - existing.sinceMs;
}
/** Exposed for tests: forget all held-since bookkeeping. */
export function resetHoldReleaseInstrumentation(): void {
heldSince.clear();
}
export async function runHoldReleaseSweep(
store: TaskStore,
deps: HoldReleaseDeps,
): Promise<HoldReleaseResult> {
const result: HoldReleaseResult = { released: [], held: [] };
const sweepStartedMs = deps.now();
const settings = await store.getSettings();
/*
@@ -423,9 +456,17 @@ export async function runHoldReleaseSweep(
// check is unaffected — this only trims the sweep pre-check cost.
const irCache = new Map<string, WorkflowIr>();
const effectiveWorkflowIdByTask = new Map<string, string>();
/*
FNXC:HoldReleaseInstrumentation 2026-07-25-14:35:
This prefetch is a SEQUENTIAL await per non-archived task, so its cost scales with total board
size rather than with the number of held cards — the prime suspect for a slow sweep on a large
board. Timed separately from the sweep total so the two are distinguishable in one log line.
*/
const prefetchStartedMs = deps.now();
for (const t of allTasks) {
effectiveWorkflowIdByTask.set(t.id, await effectiveWorkflowId(store, t.id));
}
const prefetchMs = deps.now() - prefetchStartedMs;
for (const task of allTasks) {
// Skip paused / recovery-backoff tasks exactly as the legacy scheduler does.
@@ -446,6 +487,7 @@ export async function runHoldReleaseSweep(
// manual / external-event are NEVER auto-released by the sweep.
if (release === "manual" || release === "external-event") {
trackHeld(task.id, `${release}-only`, deps.now());
result.held.push({ taskId: task.id, reason: `${release}-only` });
continue;
}
@@ -455,12 +497,14 @@ export async function runHoldReleaseSweep(
const deadline = resolveTimerDeadline(holdConfig, task);
shouldRelease = deadline !== undefined && deps.now() >= deadline;
if (!shouldRelease) {
trackHeld(task.id, "timer-not-elapsed", deps.now());
result.held.push({ taskId: task.id, reason: "timer-not-elapsed" });
continue;
}
} else if (release === "dependency") {
shouldRelease = await allDependenciesSatisfied(store, task, allTasks);
if (!shouldRelease) {
trackHeld(task.id, "deps-unsatisfied", deps.now());
result.held.push({ taskId: task.id, reason: "deps-unsatisfied" });
continue;
}
@@ -469,6 +513,7 @@ export async function runHoldReleaseSweep(
// slot is free (pre-check); the in-txn check is the authority.
const target = resolveReleaseTarget(ir, task.column, true);
if (!target) {
trackHeld(task.id, "no-downstream-capacity-column", deps.now());
result.held.push({ taskId: task.id, reason: "no-downstream-capacity-column" });
continue;
}
@@ -480,6 +525,7 @@ export async function runHoldReleaseSweep(
const budgetColumns = new Set(resolveWipBudgetColumns(ir, target));
const occupants = countCapacitySlot(allTasks, effectiveWorkflowIdByTask, budgetColumns, workflowId, capacity.countPending);
if (occupants >= capacity.limit) {
trackHeld(task.id, "downstream-full", deps.now());
result.held.push({ taskId: task.id, reason: "downstream-full" });
continue;
}
@@ -491,18 +537,60 @@ export async function runHoldReleaseSweep(
const target = resolveReleaseTarget(ir, task.column, release === "capacity");
if (!target) {
trackHeld(task.id, "no-release-target", deps.now());
result.held.push({ taskId: task.id, reason: "no-release-target" });
continue;
}
const released = await issueRelease(store, deps, task, target, ir);
if (released) {
/*
FNXC:HoldReleaseInstrumentation 2026-07-25-14:35:
Report how long the card actually waited. This is the number that answers "why didn't it move
immediately": a few hundred ms means the sweep is prompt and the wait was the poll cadence; a
multi-second/minute value with a capacity reason means the card was genuinely queued.
*/
const waitedMs = deps.now() - (heldSince.get(task.id)?.sinceMs ?? deps.now());
heldSince.delete(task.id);
schedulerLog.log(
`Hold release for ${task.id} → ${target} after ${waitedMs}ms held (release=${release})`,
);
result.released.push(task.id);
} else {
trackHeld(task.id, "move-rejected-or-no-slot", deps.now());
result.held.push({ taskId: task.id, reason: "move-rejected-or-no-slot" });
}
}
/*
FNXC:HoldReleaseInstrumentation 2026-07-25-14:35:
One summary line per sweep. Held cards carry their longest current wait so a card stuck for
minutes is visible without turning on debug logging. Info-level only when the sweep did something
or ran slowly; otherwise debug, so a quiet board does not reprint this every poll.
*/
const sweepMs = deps.now() - sweepStartedMs;
const longestHeldMs = result.held.reduce((max, h) => {
const entry = heldSince.get(h.taskId);
return entry ? Math.max(max, deps.now() - entry.sinceMs) : max;
}, 0);
const summary =
`Hold-release sweep: ${sweepMs}ms (prefetch ${prefetchMs}ms over ${allTasks.length} tasks), `
+ `released=${result.released.length}, held=${result.held.length}`
+ (longestHeldMs > 0 ? `, longest held ${longestHeldMs}ms` : "");
if (sweepMs >= SLOW_SWEEP_WARN_MS) {
schedulerLog.warn(`${summary} — sweep exceeded ${SLOW_SWEEP_WARN_MS}ms and is itself the delay`);
} else if (result.released.length > 0) {
schedulerLog.log(summary);
} else {
schedulerLog.debug(summary);
}
// Drop bookkeeping for tasks no longer held so the map tracks only live holds.
const stillHeld = new Set(result.held.map((h) => h.taskId));
for (const taskId of [...heldSince.keys()]) {
if (!stillHeld.has(taskId)) heldSince.delete(taskId);
}
return result;
}