diff --git a/docs/architecture.md b/docs/architecture.md index d621e072b..93e683ca6 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -1040,7 +1040,7 @@ Mesh configuration and post-provision managed-node operations are registered sep ### Run Audit API The run-audit system records every mutation performed by the engine across four domains: -- **Database** — task:create, task:update, task:move, etc. Node handoff/recovery emits structured events: `node:handoff:parked` (handoff denied/parked), `node:handoff:reassign-local` (local takeover approved), `node:handoff:reassign-any` (any-healthy takeover approved), and `node:lease:recovered` (abandoned lease cleared and task requeued). +- **Database** — task:create, task:update, task:move, etc. Node handoff/recovery emits structured events: `node:handoff:parked` (handoff denied/parked), `node:handoff:reassign-local` (local takeover approved), `node:handoff:reassign-any` (any-healthy takeover approved), and `node:lease:recovered` (abandoned lease cleared and task requeued). Scheduler dispatch contention also emits `scheduler:dispatch-queued-concurrency` (debounced per task+reason): metadata includes `bindingGates` (`maxConcurrent`/`maxWorktrees`/`semaphore`), per-gate `{ used, limit, slack }`, `holders`, and computed `available`. - **Git** — worktree:create, commit:create, merge:resolve, merge:audit-failure, and worktrunk lifecycle events (`worktree:worktrunk-install|create|sync|prune|remove`, plus `worktree:worktrunk-fallback`, `worktree:worktrunk-failure`, and `worktree:worktrunk-fallback-native`). Worktrunk events share metadata `{ op, binaryPath?, worktreePath?, durationMs?, exitCode?, stderrPreview?, installSource?, prunedCount? }` with `installSource` (`"release-binary" | "cargo"`) limited to successful `worktree:worktrunk-install` events and `prunedCount` limited to successful prune events when known. `worktree:worktrunk-install` is emitted only for true install actions; cache hits, configured `worktrunk.binaryPath` overrides, and `$PATH` resolutions intentionally remain silent. Dirty post-merge audit outcomes emit `merge:audit-failure` with metadata `{ mode, strategy, action, reason, issueCount, duplicateSubjectCount, touchedFileOverlapCount, verificationPassed, auditTargetLabel }`. - **Git / `merge:file-scope-violation`** — emitted by the merger when `FileScopeViolationError` aborts a squash. `target` is the task ID; metadata includes `stagedFiles`, `declaredScope`, `resetLabel`, `stagedFileCount`, and `declaredScopeCount`. Consumed by `fileScopeInvariantFailuresPerDay` in `GET /api/health/reliability` (FN-4360). - **Database / `task:auto-recover-misrouted-foreign-commit`** — emitted per dropped misrouted commit during FN-4948 contamination recovery. `target` is the recovering task; metadata carries `{ droppedSha, foreignTaskId, paths }`. @@ -1049,6 +1049,8 @@ The run-audit system records every mutation performed by the engine across four Events are tied to specific run IDs for end-to-end traceability. +For scheduler concurrency diagnostics, the queued reason now names the active limiter(s) and usage (for example `gate=maxConcurrent ...`). Read `metadata.bindingGates` first to identify the limiter. `holders.maxConcurrent` and `holders.maxWorktrees` are current `in-progress` task IDs; `holders.semaphore` mirrors that set but semaphore slots can also be consumed by triage/merge agents outside `in-progress`. So if `semaphore.used` exceeds the visible holder list, that usually indicates non-execution agents are legitimately consuming shared capacity (not stale accounting). Identical task+reason states are deduped; a newly emitted line/event indicates limiter identity or usage changed. + **Run audit endpoints:** - `GET /api/agents/:id/runs/:runId/audit` — Returns audit trail for a specific agent run - Query params: `?domain=database|git|filesystem|sandbox` for filtering diff --git a/packages/engine/src/__tests__/scheduler.test.ts b/packages/engine/src/__tests__/scheduler.test.ts index dcb00bddc..0627839fa 100644 --- a/packages/engine/src/__tests__/scheduler.test.ts +++ b/packages/engine/src/__tests__/scheduler.test.ts @@ -72,6 +72,7 @@ function createMockStore(overrides: Partial = {}): TaskStore { moveTask: vi.fn().mockResolvedValue(undefined), parseFileScopeFromPrompt: vi.fn().mockResolvedValue([]), logEntry: vi.fn().mockResolvedValue(undefined), + recordRunAuditEvent: vi.fn().mockResolvedValue(undefined), getRootDir: vi.fn().mockReturnValue("/test/project"), getTasksDir: vi.fn().mockReturnValue("/test/project/.fusion/tasks"), on: vi.fn(), @@ -950,6 +951,180 @@ describe("Scheduler", () => { }); }); + describe("FN-5008: concurrency-gate attribution", () => { + it("logs maxConcurrent as the sole binding gate", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const tasks = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + ]; + const store = createMockStore({ + listTasks: vi.fn().mockResolvedValue(tasks), + getSettings: vi.fn().mockResolvedValue({ maxConcurrent: 2, maxWorktrees: 4 }), + }); + + const scheduler = new Scheduler(store); + (scheduler as any).running = true; + await scheduler.schedule(); + + const call = (store.logEntry as ReturnType).mock.calls.find((c: unknown[]) => c[0] === "FN-C"); + expect(String(call?.[1])).toContain("gate=maxConcurrent"); + expect(String(call?.[1])).toContain("maxConcurrent used=1/2"); + expect(String(call?.[1])).toContain("holders: FN-A"); + }); + + it("logs maxWorktrees as the sole binding gate", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const tasks = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "in-progress" }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-D", column: "todo", dependencies: [] }), + ]; + const store = createMockStore({ + listTasks: vi.fn().mockResolvedValue(tasks), + getSettings: vi.fn().mockResolvedValue({ maxConcurrent: 10, maxWorktrees: 3 }), + }); + + const scheduler = new Scheduler(store); + (scheduler as any).running = true; + await scheduler.schedule(); + + const call = (store.logEntry as ReturnType).mock.calls.find((c: unknown[]) => c[0] === "FN-D"); + expect(String(call?.[1])).toContain("gate=maxWorktrees"); + expect(String(call?.[1])).toContain("maxWorktrees used=2/3"); + expect(String(call?.[1])).toContain("holders: FN-A, FN-B"); + }); + + it("logs semaphore as the sole binding gate", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const semaphore = new AgentSemaphore(1); + const tasks = [ + createMockTask({ id: "FN-A", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-B", column: "todo", dependencies: [] }), + ]; + const store = createMockStore({ + listTasks: vi.fn().mockResolvedValue(tasks), + getSettings: vi.fn().mockResolvedValue({ maxConcurrent: 10, maxWorktrees: 10 }), + }); + + const scheduler = new Scheduler(store, { semaphore }); + (scheduler as any).running = true; + await scheduler.schedule(); + + const call = (store.logEntry as ReturnType).mock.calls.find((c: unknown[]) => c[0] === "FN-B"); + expect(String(call?.[1])).toContain("gate=semaphore"); + expect(String(call?.[1])).toContain("semaphore used=0/1"); + expect(String(call?.[1])).toContain("semaphore slots may include triage/merge agents outside in-progress"); + }); + + it("lists tied binding gates in stable order", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const semaphore = new AgentSemaphore(2); + const tasks = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + ]; + const store = createMockStore({ + listTasks: vi.fn().mockResolvedValue(tasks), + getSettings: vi.fn().mockResolvedValue({ maxConcurrent: 2, maxWorktrees: 2 }), + }); + + const scheduler = new Scheduler(store, { semaphore }); + (scheduler as any).running = true; + await scheduler.schedule(); + + const call = (store.logEntry as ReturnType).mock.calls.find((c: unknown[]) => c[0] === "FN-C"); + expect(String(call?.[1])).toContain("gate=maxConcurrent, maxWorktrees"); + }); + + it("dedupes unchanged queued-concurrency logs and audit events", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const tasks = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + ]; + const store = createMockStore({ + listTasks: vi.fn().mockResolvedValue(tasks), + getSettings: vi.fn().mockResolvedValue({ maxConcurrent: 2, maxWorktrees: 4 }), + }); + + const scheduler = new Scheduler(store); + (scheduler as any).running = true; + await scheduler.schedule(); + await scheduler.schedule(); + + const concurrencyReasonCalls = (store.logEntry as ReturnType).mock.calls.filter( + (call: unknown[]) => call[0] === "FN-C" && String(call[1]).includes("queued — concurrency limit reached"), + ); + expect(concurrencyReasonCalls).toHaveLength(1); + + const auditCalls = (store.recordRunAuditEvent as ReturnType).mock.calls.filter( + (call: unknown[]) => (call[0] as { mutationType?: string } | undefined)?.mutationType === "scheduler:dispatch-queued-concurrency", + ); + expect(auditCalls).toHaveLength(1); + expect(auditCalls[0]?.[0]?.metadata?.bindingGates).toEqual(["maxConcurrent"]); + }); + + it("re-logs and re-audits when binding gate changes", async () => { + vi.mocked(existsSync).mockReturnValue(true); + vi.mocked(readFile).mockResolvedValue("# Task\nDo something"); + + const firstPass = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + ]; + const secondPass = [ + createMockTask({ id: "FN-A", column: "in-progress" }), + createMockTask({ id: "FN-B", column: "in-progress" }), + createMockTask({ id: "FN-C", column: "todo", dependencies: [] }), + createMockTask({ id: "FN-E", column: "todo", dependencies: [] }), + ]; + + let phase = 1; + const listTasks = vi.fn().mockImplementation(async () => (phase === 1 ? firstPass : secondPass)); + const getSettings = vi + .fn() + .mockImplementation(async () => (phase === 1 ? { maxConcurrent: 2, maxWorktrees: 4 } : { maxConcurrent: 10, maxWorktrees: 3 })); + + const store = createMockStore({ listTasks, getSettings }); + + const scheduler = new Scheduler(store); + (scheduler as any).running = true; + await scheduler.schedule(); + phase = 2; + await scheduler.schedule(); + + const concurrencyReasonCalls = (store.logEntry as ReturnType).mock.calls.filter( + (call: unknown[]) => String(call[1]).includes("queued — concurrency limit reached"), + ); + expect(concurrencyReasonCalls).toHaveLength(2); + expect(String(concurrencyReasonCalls[0]?.[1])).toContain("gate=maxConcurrent"); + expect(String(concurrencyReasonCalls[1]?.[1])).toContain("gate=maxWorktrees"); + + const auditCalls = (store.recordRunAuditEvent as ReturnType).mock.calls.filter( + (call: unknown[]) => (call[0] as { mutationType?: string } | undefined)?.mutationType === "scheduler:dispatch-queued-concurrency", + ); + expect(auditCalls).toHaveLength(2); + expect(auditCalls[0]?.[0]?.metadata?.bindingGates).toEqual(["maxConcurrent"]); + expect(auditCalls[1]?.[0]?.metadata?.bindingGates).toEqual(["maxWorktrees"]); + }); + }); + describe("priority-aware todo dispatch", () => { it("schedules eligible todo tasks by priority desc then createdAt asc", async () => { vi.mocked(existsSync).mockReturnValue(true);