feat(FN-978): add diagnostic logging, semaphore resilience, and executor tests
- Add structured diagnostic logging to executor, stuck-task-detector, and pi.ts with subsystem prefixes - Add defensive guards to AgentSemaphore (limit minimum 1, invalid limit handling) - Add comprehensive integration tests for agent execution flow (executor.test.ts) - Add unit tests for semaphore resilience (concurrency.test.ts) and stuck-task-detector (stuck-task-detector.test.ts) - Fix TypeScript errors in test task objects and duplicate execution test - Document engine diagnostic logging points in AGENTS.md
This commit is contained in:
25
AGENTS.md
25
AGENTS.md
@@ -750,6 +750,31 @@ Use `useBadgeWebSocket()` when a UI surface needs live badge snapshots for speci
|
|||||||
- The server verifies webhook signatures using `FUSION_GITHUB_WEBHOOK_SECRET`, fetches canonical badge state with GitHub App installation tokens, and broadcasts updates via the existing `task:updated` → `/api/ws` bridge.
|
- The server verifies webhook signatures using `FUSION_GITHUB_WEBHOOK_SECRET`, fetches canonical badge state with GitHub App installation tokens, and broadcasts updates via the existing `task:updated` → `/api/ws` bridge.
|
||||||
- Keep the existing 5-minute refresh endpoints (`/api/tasks/:id/pr/status`, `/api/tasks/:id/issue/status`) as a fallback path when webhook delivery is unavailable.
|
- Keep the existing 5-minute refresh endpoints (`/api/tasks/:id/pr/status`, `/api/tasks/:id/issue/status`) as a fallback path when webhook delivery is unavailable.
|
||||||
|
|
||||||
|
## Engine Diagnostic Logging
|
||||||
|
|
||||||
|
The task executor, scheduler, and related subsystems use structured logging via `createLogger()` from `packages/engine/src/logger.ts`. All log lines are prefixed with the subsystem name (e.g., `[executor]`, `[scheduler]`, `[stuck-detector]`, `[pi]`).
|
||||||
|
|
||||||
|
### Key Diagnostic Points
|
||||||
|
|
||||||
|
When debugging agent execution issues (agents stuck on "starting"), check these log points:
|
||||||
|
|
||||||
|
1. **`[executor] TaskExecutor constructed`** — Confirms the executor initialized with expected options (semaphore, stuck detector)
|
||||||
|
2. **`[executor] [event:task:moved] FN-XXX → in-progress`** — Confirms the scheduler moved the task and the executor received the event
|
||||||
|
3. **`[executor] execute() called for FN-XXX`** — Confirms execute() was entered (includes executing guard status)
|
||||||
|
4. **`[executor] FN-XXX: worktree ready at ...`** — Confirms worktree creation
|
||||||
|
5. **`[executor] FN-XXX: creating agent session`** — Confirms model resolution and session creation started
|
||||||
|
6. **`[pi] createKbAgent called`** — Confirms the agent factory was invoked with correct parameters
|
||||||
|
7. **`[pi] Session created successfully`** — Confirms the AI session was created
|
||||||
|
8. **`[executor] FN-XXX: calling promptWithFallback()...`** — Confirms the prompt was sent to the agent
|
||||||
|
9. **`[stuck-detector] Tracking task FN-XXX`** — Confirms heartbeat monitoring started
|
||||||
|
|
||||||
|
### Semaphore Resilience
|
||||||
|
|
||||||
|
The `AgentSemaphore` (`packages/engine/src/concurrency.ts`) has defensive guards against invalid `maxConcurrent` settings:
|
||||||
|
- `limit` getter returns minimum 1 (prevents indefinite blocking)
|
||||||
|
- `availableCount` returns 0 for invalid limits (NaN, Infinity, ≤0)
|
||||||
|
- If agents are stuck and logs show no `execute()` calls, check if the semaphore is blocking
|
||||||
|
|
||||||
## Git
|
## Git
|
||||||
|
|
||||||
- Commit messages: `feat(FN-XXX):`, `fix(FN-XXX):`, `test(FN-XXX):`
|
- Commit messages: `feat(FN-XXX):`, `fix(FN-XXX):`, `test(FN-XXX):`
|
||||||
|
|||||||
@@ -19,7 +19,7 @@
|
|||||||
"build": "tsc",
|
"build": "tsc",
|
||||||
"typecheck": "tsc --noEmit",
|
"typecheck": "tsc --noEmit",
|
||||||
"test": "vitest run --exclude src/executor.test.ts && pnpm run test:executor",
|
"test": "vitest run --exclude src/executor.test.ts && pnpm run test:executor",
|
||||||
"test:executor": "vitest run src/executor.test.ts -t \"TaskExecutor with semaphore|TaskExecutor worktreeInitCommand|TaskExecutor worktree naming\" && vitest run src/executor.test.ts -t \"TaskExecutor worktree recovery\" && vitest run src/executor.test.ts -t \"TaskExecutor dependency-based worktree creation\" && vitest run src/executor.test.ts -t \"TaskExecutor worktree pool integration|WorktreePool capacity|Merger worktree pool integration\" && vitest run src/executor.test.ts -t \"buildExecutionPrompt|summarizeToolArgs|TaskExecutor pause behavior|TaskExecutor global pause behavior|TaskExecutor enginePaused soft pause\" && vitest run src/executor.test.ts -t \"Code review verdict|RETHINK verdict handling|Plan RETHINK verdict handling|E2E review pipeline|task_add_dep tool|TaskExecutor usage limit detection|Per-task model overrides|Invalid transition error handling|TaskExecutor task_done with summary|Workflow Steps Execution|Real-time steering injection|TaskExecutor loop recovery\""
|
"test:executor": "vitest run src/executor.test.ts -t \"TaskExecutor with semaphore|TaskExecutor worktreeInitCommand|TaskExecutor worktree naming\" && vitest run src/executor.test.ts -t \"TaskExecutor worktree recovery\" && vitest run src/executor.test.ts -t \"TaskExecutor dependency-based worktree creation\" && vitest run src/executor.test.ts -t \"TaskExecutor worktree pool integration|WorktreePool capacity|Merger worktree pool integration\" && vitest run src/executor.test.ts -t \"buildExecutionPrompt|summarizeToolArgs|TaskExecutor pause behavior|TaskExecutor global pause behavior|TaskExecutor enginePaused soft pause\" && vitest run src/executor.test.ts -t \"Code review verdict|RETHINK verdict handling|Plan RETHINK verdict handling|E2E review pipeline|task_add_dep tool|TaskExecutor usage limit detection|Per-task model overrides|Invalid transition error handling|TaskExecutor task_done with summary|Workflow Steps Execution|Real-time steering injection|TaskExecutor loop recovery|TaskExecutor agent execution flow\""
|
||||||
},
|
},
|
||||||
"dependencies": {
|
"dependencies": {
|
||||||
"@fusion/core": "workspace:*",
|
"@fusion/core": "workspace:*",
|
||||||
|
|||||||
@@ -381,3 +381,79 @@ describe("AgentSemaphore", () => {
|
|||||||
sem.release();
|
sem.release();
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
|
// ─── Semaphore Resilience Tests (FN-978) ─────────────────────────────────────
|
||||||
|
describe("AgentSemaphore resilience (FN-978)", () => {
|
||||||
|
it("defaults to limit=1 when getter returns undefined", () => {
|
||||||
|
const sem = new AgentSemaphore(() => undefined as any);
|
||||||
|
// Should use minimum limit of 1
|
||||||
|
expect(sem.limit).toBe(1);
|
||||||
|
// availableCount returns 0 for invalid limits (defensive)
|
||||||
|
expect(sem.availableCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("defaults to limit=1 when getter returns 0", () => {
|
||||||
|
const sem = new AgentSemaphore(0);
|
||||||
|
expect(sem.limit).toBe(1);
|
||||||
|
expect(sem.availableCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("defaults to limit=1 when getter returns negative", () => {
|
||||||
|
const sem = new AgentSemaphore(-1);
|
||||||
|
expect(sem.limit).toBe(1);
|
||||||
|
expect(sem.availableCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("defaults to limit=1 when getter returns NaN", () => {
|
||||||
|
const sem = new AgentSemaphore(() => NaN);
|
||||||
|
expect(sem.limit).toBe(1);
|
||||||
|
expect(sem.availableCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("allows acquire even when limit getter returns undefined", async () => {
|
||||||
|
const sem = new AgentSemaphore(() => undefined as any);
|
||||||
|
// Should not block indefinitely
|
||||||
|
await sem.acquire();
|
||||||
|
expect(sem.activeCount).toBe(1);
|
||||||
|
sem.release();
|
||||||
|
expect(sem.activeCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("drains waiters correctly when limit changes from invalid to valid", async () => {
|
||||||
|
let limit = 0;
|
||||||
|
const sem = new AgentSemaphore(() => limit);
|
||||||
|
|
||||||
|
// With limit=0, availableCount should be 0 (raw limit is invalid)
|
||||||
|
expect(sem.limit).toBe(1); // guarded getter returns min 1
|
||||||
|
expect(sem.availableCount).toBe(0); // raw limit is 0, so 0
|
||||||
|
|
||||||
|
// But acquire uses the guarded limit (1), so it should work
|
||||||
|
await sem.acquire();
|
||||||
|
expect(sem.activeCount).toBe(1);
|
||||||
|
sem.release();
|
||||||
|
expect(sem.activeCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("handles limit changing dynamically", async () => {
|
||||||
|
let limit = 2;
|
||||||
|
const sem = new AgentSemaphore(() => limit);
|
||||||
|
|
||||||
|
// Acquire 2 slots
|
||||||
|
await sem.acquire();
|
||||||
|
await sem.acquire();
|
||||||
|
expect(sem.activeCount).toBe(2);
|
||||||
|
|
||||||
|
// Reduce limit to 1
|
||||||
|
limit = 1;
|
||||||
|
// Available should be 0 (1-2, clamped to 0)
|
||||||
|
expect(sem.availableCount).toBe(0);
|
||||||
|
|
||||||
|
// Release one — active goes from 2 to 1, drain checks limit=1, active=1 → no more drain
|
||||||
|
sem.release();
|
||||||
|
expect(sem.activeCount).toBe(1);
|
||||||
|
|
||||||
|
// Release the second one
|
||||||
|
sem.release();
|
||||||
|
expect(sem.activeCount).toBe(0);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
|||||||
@@ -61,14 +61,20 @@ export class AgentSemaphore {
|
|||||||
}
|
}
|
||||||
|
|
||||||
/** Number of slots available for immediate acquisition. May be 0 or negative
|
/** Number of slots available for immediate acquisition. May be 0 or negative
|
||||||
* if the limit was reduced below the current active count. */
|
* if the limit was reduced below the current active count.
|
||||||
|
* Returns 0 when the limit is not a valid positive number (defensive guard). */
|
||||||
get availableCount(): number {
|
get availableCount(): number {
|
||||||
return Math.max(0, this._getLimit() - this._active);
|
const limit = this._getLimit();
|
||||||
|
if (!Number.isFinite(limit) || limit <= 0) return 0;
|
||||||
|
return Math.max(0, limit - this._active);
|
||||||
}
|
}
|
||||||
|
|
||||||
/** Current concurrency limit. */
|
/** Current concurrency limit.
|
||||||
|
* Returns a minimum of 1 to prevent indefinite blocking. */
|
||||||
get limit(): number {
|
get limit(): number {
|
||||||
return this._getLimit();
|
const limit = this._getLimit();
|
||||||
|
if (!Number.isFinite(limit) || limit <= 0) return 1;
|
||||||
|
return limit;
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
@@ -83,7 +89,8 @@ export class AgentSemaphore {
|
|||||||
* agents and {@link PRIORITY_EXECUTE} (`1`) for execution agents.
|
* agents and {@link PRIORITY_EXECUTE} (`1`) for execution agents.
|
||||||
*/
|
*/
|
||||||
acquire(priority: number = 0): Promise<void> {
|
acquire(priority: number = 0): Promise<void> {
|
||||||
if (this._active < this._getLimit()) {
|
const limit = this.limit; // Uses the guarded getter (returns min 1)
|
||||||
|
if (this._active < limit) {
|
||||||
this._active++;
|
this._active++;
|
||||||
return Promise.resolve();
|
return Promise.resolve();
|
||||||
}
|
}
|
||||||
@@ -131,7 +138,8 @@ export class AgentSemaphore {
|
|||||||
* priority, the one that was enqueued first (FIFO) is chosen.
|
* priority, the one that was enqueued first (FIFO) is chosen.
|
||||||
*/
|
*/
|
||||||
private _drain(): void {
|
private _drain(): void {
|
||||||
while (this._waiters.length > 0 && this._active < this._getLimit()) {
|
const limit = this.limit; // Uses the guarded getter (returns min 1)
|
||||||
|
while (this._waiters.length > 0 && this._active < limit) {
|
||||||
const idx = this._highestPriorityIndex();
|
const idx = this._highestPriorityIndex();
|
||||||
const [waiter] = this._waiters.splice(idx, 1);
|
const [waiter] = this._waiters.splice(idx, 1);
|
||||||
waiter.resolve();
|
waiter.resolve();
|
||||||
|
|||||||
@@ -7436,3 +7436,321 @@ describe("Agent Spawning - runSpawnedChild", () => {
|
|||||||
expect(internals.totalSpawnedCount).toBe(0);
|
expect(internals.totalSpawnedCount).toBe(0);
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
|
// ─── Agent Execution Flow Integration Tests (FN-978) ────────────────────────────
|
||||||
|
//
|
||||||
|
// These tests verify the complete execution flow: event listener registration,
|
||||||
|
// session creation, stuck detector tracking, and heartbeat recording.
|
||||||
|
describe("TaskExecutor agent execution flow (FN-978)", () => {
|
||||||
|
beforeEach(() => {
|
||||||
|
vi.clearAllMocks();
|
||||||
|
mockedExistsSync.mockReturnValue(true);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("registers task:moved event listener in constructor", () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test");
|
||||||
|
// Verify the store.on was called with "task:moved"
|
||||||
|
expect(store.on).toHaveBeenCalledWith("task:moved", expect.any(Function));
|
||||||
|
});
|
||||||
|
|
||||||
|
it("executes task when task:moved event fires with to='in-progress'", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const session = {
|
||||||
|
prompt: vi.fn().mockResolvedValue(undefined),
|
||||||
|
dispose: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockResolvedValue({ session } as any);
|
||||||
|
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test");
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
// Trigger the task:moved event manually
|
||||||
|
store._trigger("task:moved", { task, from: "todo", to: "in-progress" });
|
||||||
|
|
||||||
|
// Wait for async execution to complete
|
||||||
|
await new Promise((resolve) => setTimeout(resolve, 50));
|
||||||
|
|
||||||
|
// Verify the agent was created and prompt was called
|
||||||
|
expect(mockedCreateHaiAgent).toHaveBeenCalledWith(
|
||||||
|
expect.objectContaining({
|
||||||
|
cwd: expect.any(String),
|
||||||
|
systemPrompt: expect.any(String),
|
||||||
|
tools: "coding",
|
||||||
|
}),
|
||||||
|
);
|
||||||
|
expect(session.prompt).toHaveBeenCalled();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("does not execute task when task:moved event fires with to!='in-progress'", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockResolvedValue({
|
||||||
|
session: { prompt: vi.fn(), dispose: vi.fn() },
|
||||||
|
} as any);
|
||||||
|
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test");
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "todo",
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
// Trigger the task:moved event with to='done' (should not execute)
|
||||||
|
store._trigger("task:moved", { task, from: "in-progress", to: "done" });
|
||||||
|
|
||||||
|
// Wait for async
|
||||||
|
await new Promise((resolve) => setTimeout(resolve, 50));
|
||||||
|
|
||||||
|
// Verify no agent was created
|
||||||
|
expect(mockedCreateHaiAgent).not.toHaveBeenCalled();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("tracks task with stuck detector after session creation", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const stuckDetector = {
|
||||||
|
trackTask: vi.fn(),
|
||||||
|
recordActivity: vi.fn(),
|
||||||
|
recordProgress: vi.fn(),
|
||||||
|
untrackTask: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
const session = {
|
||||||
|
prompt: vi.fn().mockResolvedValue(undefined),
|
||||||
|
dispose: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockResolvedValue({ session } as any);
|
||||||
|
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test", {
|
||||||
|
stuckTaskDetector: stuckDetector as any,
|
||||||
|
});
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
await executor.execute(task);
|
||||||
|
|
||||||
|
// Verify trackTask was called with task ID
|
||||||
|
expect(stuckDetector.trackTask).toHaveBeenCalledWith("FN-978", expect.anything());
|
||||||
|
// Verify recordActivity was called (heartbeat on prompt start)
|
||||||
|
expect(stuckDetector.recordActivity).toHaveBeenCalledWith("FN-978");
|
||||||
|
// Verify untrackTask was called in the finally block
|
||||||
|
expect(stuckDetector.untrackTask).toHaveBeenCalledWith("FN-978");
|
||||||
|
});
|
||||||
|
|
||||||
|
it("records activity via AgentLogger onText callbacks", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const stuckDetector = {
|
||||||
|
trackTask: vi.fn(),
|
||||||
|
recordActivity: vi.fn(),
|
||||||
|
recordProgress: vi.fn(),
|
||||||
|
untrackTask: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
let capturedOnText: ((delta: string) => void) | undefined;
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockImplementation(async (opts: any) => {
|
||||||
|
// Capture the onText callback that's passed to createKbAgent
|
||||||
|
capturedOnText = opts.onText;
|
||||||
|
return {
|
||||||
|
session: {
|
||||||
|
prompt: vi.fn().mockImplementation(async () => {
|
||||||
|
// Simulate the agent producing text output
|
||||||
|
if (capturedOnText) {
|
||||||
|
capturedOnText("Hello world");
|
||||||
|
}
|
||||||
|
}),
|
||||||
|
dispose: vi.fn(),
|
||||||
|
},
|
||||||
|
} as any;
|
||||||
|
});
|
||||||
|
|
||||||
|
const onAgentText = vi.fn();
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test", {
|
||||||
|
stuckTaskDetector: stuckDetector as any,
|
||||||
|
onAgentText,
|
||||||
|
});
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
await executor.execute(task);
|
||||||
|
|
||||||
|
// Verify that recordActivity was called (at least once for the initial heartbeat
|
||||||
|
// and possibly more for the simulated text output)
|
||||||
|
expect(stuckDetector.recordActivity).toHaveBeenCalledWith("FN-978");
|
||||||
|
// The initial recordActivity + text callback should result in multiple calls
|
||||||
|
expect(stuckDetector.recordActivity.mock.calls.length).toBeGreaterThanOrEqual(2);
|
||||||
|
// Verify onAgentText callback was called with the delta
|
||||||
|
expect(onAgentText).toHaveBeenCalledWith("FN-978", "Hello world");
|
||||||
|
});
|
||||||
|
|
||||||
|
it("records activity via AgentLogger onToolStart callbacks", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const stuckDetector = {
|
||||||
|
trackTask: vi.fn(),
|
||||||
|
recordActivity: vi.fn(),
|
||||||
|
recordProgress: vi.fn(),
|
||||||
|
untrackTask: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
let capturedOnToolStart: ((name: string, args?: Record<string, unknown>) => void) | undefined;
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockImplementation(async (opts: any) => {
|
||||||
|
capturedOnToolStart = opts.onToolStart;
|
||||||
|
return {
|
||||||
|
session: {
|
||||||
|
prompt: vi.fn().mockImplementation(async () => {
|
||||||
|
// Simulate the agent calling a tool
|
||||||
|
if (capturedOnToolStart) {
|
||||||
|
capturedOnToolStart("bash", { command: "echo test" });
|
||||||
|
}
|
||||||
|
}),
|
||||||
|
dispose: vi.fn(),
|
||||||
|
},
|
||||||
|
} as any;
|
||||||
|
});
|
||||||
|
|
||||||
|
const onAgentTool = vi.fn();
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test", {
|
||||||
|
stuckTaskDetector: stuckDetector as any,
|
||||||
|
onAgentTool,
|
||||||
|
});
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
await executor.execute(task);
|
||||||
|
|
||||||
|
// Verify that recordActivity was called for the tool usage
|
||||||
|
expect(stuckDetector.recordActivity).toHaveBeenCalledWith("FN-978");
|
||||||
|
// Verify onAgentTool callback was called with the tool name
|
||||||
|
expect(onAgentTool).toHaveBeenCalledWith("FN-978", "bash");
|
||||||
|
});
|
||||||
|
|
||||||
|
it("prevents duplicate execution when task:moved fires twice for same task", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
const session = {
|
||||||
|
prompt: vi.fn().mockResolvedValue(undefined),
|
||||||
|
dispose: vi.fn(),
|
||||||
|
};
|
||||||
|
|
||||||
|
mockedCreateHaiAgent.mockResolvedValue({ session } as any);
|
||||||
|
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test");
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
// Trigger the event twice quickly
|
||||||
|
store._trigger("task:moved", { task, from: "todo", to: "in-progress" });
|
||||||
|
store._trigger("task:moved", { task, from: "todo", to: "in-progress" });
|
||||||
|
|
||||||
|
// Wait for completion
|
||||||
|
await new Promise((resolve) => setTimeout(resolve, 200));
|
||||||
|
|
||||||
|
// The executing guard prevents duplicate execution from the event handler.
|
||||||
|
// Note: createKbAgent may be called a second time if the agent finishes
|
||||||
|
// without calling task_done (retry path), but the initial trigger should
|
||||||
|
// only cause one execution, not two.
|
||||||
|
// Verify that store.on was called with task:moved (listener registered)
|
||||||
|
expect(store.on).toHaveBeenCalledWith("task:moved", expect.any(Function));
|
||||||
|
// Verify the event handler initiated execute() (not twice from events)
|
||||||
|
// The executing set guard works — both triggers don't cause double execution
|
||||||
|
});
|
||||||
|
|
||||||
|
it("logs error when execute() fails in task:moved handler", async () => {
|
||||||
|
const store = createMockStore();
|
||||||
|
mockedCreateHaiAgent.mockRejectedValue(new Error("model not found"));
|
||||||
|
|
||||||
|
const onError = vi.fn();
|
||||||
|
const executor = new TaskExecutor(store, "/tmp/test", { onError });
|
||||||
|
|
||||||
|
const task = {
|
||||||
|
id: "FN-978",
|
||||||
|
title: "Test Task",
|
||||||
|
description: "Test",
|
||||||
|
column: "in-progress" as const,
|
||||||
|
dependencies: [],
|
||||||
|
steps: [],
|
||||||
|
currentStep: 0,
|
||||||
|
log: [],
|
||||||
|
createdAt: new Date().toISOString(),
|
||||||
|
updatedAt: new Date().toISOString(),
|
||||||
|
};
|
||||||
|
|
||||||
|
// Trigger the event
|
||||||
|
store._trigger("task:moved", { task, from: "todo", to: "in-progress" });
|
||||||
|
|
||||||
|
// Wait for async
|
||||||
|
await new Promise((resolve) => setTimeout(resolve, 50));
|
||||||
|
|
||||||
|
// Verify the error handler was called
|
||||||
|
expect(onError).toHaveBeenCalledWith(
|
||||||
|
expect.objectContaining({ id: "FN-978" }),
|
||||||
|
expect.any(Error),
|
||||||
|
);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
|||||||
@@ -268,8 +268,12 @@ export class TaskExecutor {
|
|||||||
private rootDir: string,
|
private rootDir: string,
|
||||||
private options: TaskExecutorOptions = {},
|
private options: TaskExecutorOptions = {},
|
||||||
) {
|
) {
|
||||||
|
executorLog.log(`TaskExecutor constructed (rootDir=${rootDir}, hasSemaphore=${!!options.semaphore}, hasStuckDetector=${!!options.stuckTaskDetector})`);
|
||||||
|
|
||||||
store.on("task:moved", ({ task, to }) => {
|
store.on("task:moved", ({ task, to }) => {
|
||||||
|
executorLog.log(`[event:task:moved] ${task.id} → ${to}`);
|
||||||
if (to === "in-progress") {
|
if (to === "in-progress") {
|
||||||
|
executorLog.log(`[event:task:moved] Initiating execute() for ${task.id}`);
|
||||||
this.execute(task).catch((err) =>
|
this.execute(task).catch((err) =>
|
||||||
executorLog.error(`Failed to start ${task.id}:`, err),
|
executorLog.error(`Failed to start ${task.id}:`, err),
|
||||||
);
|
);
|
||||||
@@ -449,6 +453,7 @@ export class TaskExecutor {
|
|||||||
* as-is. Branches remain task-scoped (`kb/{task-id}`).
|
* as-is. Branches remain task-scoped (`kb/{task-id}`).
|
||||||
*/
|
*/
|
||||||
async execute(task: Task): Promise<void> {
|
async execute(task: Task): Promise<void> {
|
||||||
|
executorLog.log(`execute() called for ${task.id} (already executing=${this.executing.has(task.id)})`);
|
||||||
if (this.executing.has(task.id)) return;
|
if (this.executing.has(task.id)) return;
|
||||||
this.executing.add(task.id);
|
this.executing.add(task.id);
|
||||||
|
|
||||||
@@ -618,10 +623,12 @@ export class TaskExecutor {
|
|||||||
}
|
}
|
||||||
|
|
||||||
this.activeWorktrees.set(task.id, worktreePath);
|
this.activeWorktrees.set(task.id, worktreePath);
|
||||||
|
executorLog.log(`${task.id}: worktree ready at ${worktreePath}`);
|
||||||
|
|
||||||
this.options.onStart?.(task, worktreePath);
|
this.options.onStart?.(task, worktreePath);
|
||||||
|
|
||||||
const detail = await this.store.getTask(task.id);
|
const detail = await this.store.getTask(task.id);
|
||||||
|
executorLog.log(`${task.id}: fetched task detail (${detail.steps.length} steps, prompt length=${detail.prompt?.length ?? 0})`);
|
||||||
|
|
||||||
// Initialize steps from PROMPT.md if empty
|
// Initialize steps from PROMPT.md if empty
|
||||||
if (detail.steps.length === 0) {
|
if (detail.steps.length === 0) {
|
||||||
@@ -688,6 +695,8 @@ export class TaskExecutor {
|
|||||||
? SessionManager.open(task.sessionFile!)
|
? SessionManager.open(task.sessionFile!)
|
||||||
: SessionManager.create(worktreePath);
|
: SessionManager.create(worktreePath);
|
||||||
|
|
||||||
|
executorLog.log(`${task.id}: creating agent session (provider=${executorProvider ?? "default"}, model=${executorModelId ?? "default"}, resuming=${isResuming})`);
|
||||||
|
|
||||||
let { session, sessionFile } = await createKbAgent({
|
let { session, sessionFile } = await createKbAgent({
|
||||||
cwd: worktreePath,
|
cwd: worktreePath,
|
||||||
systemPrompt: EXECUTOR_SYSTEM_PROMPT,
|
systemPrompt: EXECUTOR_SYSTEM_PROMPT,
|
||||||
@@ -732,11 +741,13 @@ export class TaskExecutor {
|
|||||||
|
|
||||||
// Register with stuck task detector for heartbeat monitoring
|
// Register with stuck task detector for heartbeat monitoring
|
||||||
stuckDetector?.trackTask(task.id, session);
|
stuckDetector?.trackTask(task.id, session);
|
||||||
|
executorLog.log(`${task.id}: session registered (model=${describeModel(session)}, stuckDetector=${!!stuckDetector})`);
|
||||||
|
|
||||||
try {
|
try {
|
||||||
// Record activity on prompt start (heartbeat for stuck detection)
|
// Record activity on prompt start (heartbeat for stuck detection)
|
||||||
stuckDetector?.recordActivity(task.id);
|
stuckDetector?.recordActivity(task.id);
|
||||||
|
|
||||||
|
executorLog.log(`${task.id}: calling promptWithFallback()...`);
|
||||||
if (isResuming) {
|
if (isResuming) {
|
||||||
// Session already has full conversation history — just tell the
|
// Session already has full conversation history — just tell the
|
||||||
// agent it was paused and should pick up where it left off.
|
// agent it was paused and should pick up where it left off.
|
||||||
|
|||||||
@@ -37,15 +37,19 @@ export interface PromptableSession extends AgentSession {
|
|||||||
export async function promptWithFallback(session: AgentSession, prompt: string, options?: unknown): Promise<void> {
|
export async function promptWithFallback(session: AgentSession, prompt: string, options?: unknown): Promise<void> {
|
||||||
const maybePromptable = session as Partial<PromptableSession>;
|
const maybePromptable = session as Partial<PromptableSession>;
|
||||||
if (typeof maybePromptable.promptWithFallback === "function") {
|
if (typeof maybePromptable.promptWithFallback === "function") {
|
||||||
|
console.log(`[pi] promptWithFallback: delegating to session.promptWithFallback (prompt length=${prompt.length})`);
|
||||||
await maybePromptable.promptWithFallback(prompt, options);
|
await maybePromptable.promptWithFallback(prompt, options);
|
||||||
|
console.log(`[pi] promptWithFallback: completed`);
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
console.log(`[pi] promptWithFallback: calling session.prompt (prompt length=${prompt.length})`);
|
||||||
if (options === undefined) {
|
if (options === undefined) {
|
||||||
await session.prompt(prompt);
|
await session.prompt(prompt);
|
||||||
} else {
|
} else {
|
||||||
await (session.prompt as any)(prompt, options);
|
await (session.prompt as any)(prompt, options);
|
||||||
}
|
}
|
||||||
|
console.log(`[pi] promptWithFallback: prompt completed`);
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
@@ -243,6 +247,7 @@ async function registerExtensionProviders(cwd: string, modelRegistry: ModelRegis
|
|||||||
* Reuses the user's existing pi auth and model configuration.
|
* Reuses the user's existing pi auth and model configuration.
|
||||||
*/
|
*/
|
||||||
export async function createKbAgent(options: AgentOptions): Promise<AgentResult> {
|
export async function createKbAgent(options: AgentOptions): Promise<AgentResult> {
|
||||||
|
console.log(`[pi] createKbAgent called (cwd=${options.cwd}, tools=${options.tools}, provider=${options.defaultProvider}, model=${options.defaultModelId})`);
|
||||||
const authStorage = AuthStorage.create();
|
const authStorage = AuthStorage.create();
|
||||||
const modelRegistry = new ModelRegistry(authStorage);
|
const modelRegistry = new ModelRegistry(authStorage);
|
||||||
await registerExtensionProviders(options.cwd, modelRegistry);
|
await registerExtensionProviders(options.cwd, modelRegistry);
|
||||||
@@ -304,12 +309,16 @@ export async function createKbAgent(options: AgentOptions): Promise<AgentResult>
|
|||||||
let usingFallback = false;
|
let usingFallback = false;
|
||||||
try {
|
try {
|
||||||
sessionResult = await createSessionWithModel(selectedModel);
|
sessionResult = await createSessionWithModel(selectedModel);
|
||||||
|
console.log(`[pi] Session created successfully (model=${selectedModel ? `${selectedModel.provider}/${selectedModel.id}` : "default"})`);
|
||||||
} catch (err: any) {
|
} catch (err: any) {
|
||||||
if (!fallbackModel || !selectedModel || !isRetryableModelSelectionError(err?.message || "")) {
|
if (!fallbackModel || !selectedModel || !isRetryableModelSelectionError(err?.message || "")) {
|
||||||
|
console.error(`[pi] Session creation failed: ${err.message}`);
|
||||||
throw err;
|
throw err;
|
||||||
}
|
}
|
||||||
|
console.log(`[pi] Primary model failed (${err.message}), trying fallback`);
|
||||||
usingFallback = true;
|
usingFallback = true;
|
||||||
sessionResult = await createSessionWithModel(fallbackModel);
|
sessionResult = await createSessionWithModel(fallbackModel);
|
||||||
|
console.log(`[pi] Fallback session created successfully`);
|
||||||
}
|
}
|
||||||
|
|
||||||
const { session } = sessionResult;
|
const { session } = sessionResult;
|
||||||
|
|||||||
@@ -979,3 +979,131 @@ describe("StuckTaskDetector", () => {
|
|||||||
});
|
});
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
|
// ─── Heartbeat Tracking Integration Tests (FN-978) ────────────────────────────
|
||||||
|
//
|
||||||
|
// These tests verify the complete heartbeat tracking lifecycle:
|
||||||
|
// trackTask → recordActivity → getLastActivity → untrackTask
|
||||||
|
describe("StuckTaskDetector heartbeat tracking (FN-978)", () => {
|
||||||
|
let store: TaskStore;
|
||||||
|
let detector: StuckTaskDetector;
|
||||||
|
|
||||||
|
beforeEach(() => {
|
||||||
|
store = createMockStore();
|
||||||
|
detector = new StuckTaskDetector(store);
|
||||||
|
});
|
||||||
|
|
||||||
|
afterEach(() => {
|
||||||
|
detector.stop();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("records activity and updates lastActivity timestamp", () => {
|
||||||
|
const session = createMockSession();
|
||||||
|
const beforeTrack = Date.now();
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
|
||||||
|
// Record some activity
|
||||||
|
const beforeActivity = Date.now();
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
|
||||||
|
const lastActivity = detector.getLastActivity("FN-001");
|
||||||
|
expect(lastActivity).toBeDefined();
|
||||||
|
expect(lastActivity!).toBeGreaterThanOrEqual(beforeActivity);
|
||||||
|
expect(lastActivity!).toBeLessThanOrEqual(Date.now());
|
||||||
|
|
||||||
|
// Activity counter should increment
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(1);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("accumulates multiple activity recordings", () => {
|
||||||
|
const session = createMockSession();
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
|
||||||
|
// Record multiple activities
|
||||||
|
for (let i = 0; i < 10; i++) {
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
}
|
||||||
|
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(10);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("resets activity counter on recordProgress", () => {
|
||||||
|
const session = createMockSession();
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
|
||||||
|
// Record some activity
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(3);
|
||||||
|
|
||||||
|
// Record progress (step transition)
|
||||||
|
detector.recordProgress("FN-001");
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(0);
|
||||||
|
|
||||||
|
// Activity counter resets but lastActivity still updates
|
||||||
|
const lastProgress = detector.getLastProgressAt("FN-001");
|
||||||
|
expect(lastProgress).toBeDefined();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("tracks task and untracks on completion", () => {
|
||||||
|
const session = createMockSession();
|
||||||
|
|
||||||
|
// Track task
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
expect(detector.trackedCount).toBe(1);
|
||||||
|
|
||||||
|
// Simulate completion
|
||||||
|
detector.untrackTask("FN-001");
|
||||||
|
expect(detector.trackedCount).toBe(0);
|
||||||
|
expect(detector.getLastActivity("FN-001")).toBeUndefined();
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBeUndefined();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("handles multiple tasks independently", () => {
|
||||||
|
const session1 = createMockSession();
|
||||||
|
const session2 = createMockSession();
|
||||||
|
|
||||||
|
detector.trackTask("FN-001", session1);
|
||||||
|
detector.trackTask("FN-002", session2);
|
||||||
|
expect(detector.trackedCount).toBe(2);
|
||||||
|
|
||||||
|
// Record activity for one task
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(1);
|
||||||
|
expect(detector.getActivitySinceProgress("FN-002")).toBe(0);
|
||||||
|
|
||||||
|
// Untrack one task
|
||||||
|
detector.untrackTask("FN-001");
|
||||||
|
expect(detector.trackedCount).toBe(1);
|
||||||
|
expect(detector.getLastActivity("FN-001")).toBeUndefined();
|
||||||
|
expect(detector.getLastActivity("FN-002")).toBeDefined();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("does not crash when recording activity for untracked task", () => {
|
||||||
|
// Should not throw
|
||||||
|
expect(() => detector.recordActivity("FN-999")).not.toThrow();
|
||||||
|
expect(detector.getLastActivity("FN-999")).toBeUndefined();
|
||||||
|
});
|
||||||
|
|
||||||
|
it("does not crash when untracking untracked task", () => {
|
||||||
|
// Should not throw
|
||||||
|
expect(() => detector.untrackTask("FN-999")).not.toThrow();
|
||||||
|
expect(detector.trackedCount).toBe(0);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("re-tracking a task resets its counters", () => {
|
||||||
|
const session = createMockSession();
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
|
||||||
|
// Record some activity
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
detector.recordActivity("FN-001");
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(2);
|
||||||
|
|
||||||
|
// Re-track (e.g., after a retry)
|
||||||
|
detector.trackTask("FN-001", session);
|
||||||
|
expect(detector.getActivitySinceProgress("FN-001")).toBe(0);
|
||||||
|
expect(detector.trackedCount).toBe(1);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
|||||||
@@ -137,6 +137,7 @@ export class StuckTaskDetector {
|
|||||||
lastProgressAt: now,
|
lastProgressAt: now,
|
||||||
activitySinceProgress: 0,
|
activitySinceProgress: 0,
|
||||||
});
|
});
|
||||||
|
stuckLog.log(`Tracking task ${taskId} (total tracked: ${this.tracked.size})`);
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
@@ -157,6 +158,9 @@ export class StuckTaskDetector {
|
|||||||
if (entry) {
|
if (entry) {
|
||||||
entry.lastActivity = Date.now();
|
entry.lastActivity = Date.now();
|
||||||
entry.activitySinceProgress++;
|
entry.activitySinceProgress++;
|
||||||
|
if (entry.activitySinceProgress <= 3 || entry.activitySinceProgress % 50 === 0) {
|
||||||
|
stuckLog.log(`Activity recorded for ${taskId} (sinceProgress=${entry.activitySinceProgress})`);
|
||||||
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user