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

feat(HAI-113): add structured logger and replace console calls

Browse Source 
- Create logger module with log levels and structured output (packages/engine/src/logger.ts)
- Replace console.log/warn/error calls with structured logger across engine modules
- Export logger from engine package index
- Add comprehensive tests for logger functionality
- Clean up CI/release workflows and update docs
This commit is contained in:
Dustin Byrne
2026-03-26 21:54:29 -04:00
parent d147a51d16
commit 1c5eb494db
8 changed files with 187 additions and 51 deletions
Download Patch File Download Diff File Expand all files Collapse all files

43
packages/engine/src/executor.ts
View File

@@ -11,6 +11,7 @@ import type { ToolDefinition } from "@mariozechner/pi-coding-agent";
import type { AgentSemaphore } from "./concurrency.js";
import type { WorktreePool } from "./worktree-pool.js";
import { AgentLogger } from "./agent-logger.js";
import { executorLog, reviewerLog } from "./logger.js";
// Re-export for backward compatibility (tests import from executor.ts)
export { summarizeToolArgs } from "./agent-logger.js";
@@ -150,7 +151,7 @@ export class TaskExecutor {
store.on("task:moved", ({ task, to }) => {
if (to === "in-progress") {
this.execute(task).catch((err) =>
console.error(`[executor] Failed to start ${task.id}:`, err),
executorLog.error(`Failed to start ${task.id}:`, err),
);
}
});
@@ -158,7 +159,7 @@ export class TaskExecutor {
// When a task is paused while executing, terminate the agent session.
store.on("task:updated", (task) => {
if (task.paused && this.activeSessions.has(task.id)) {
console.log(`[executor] Pausing ${task.id} — terminating agent session`);
executorLog.log(`Pausing ${task.id} — terminating agent session`);
this.pausedAborted.add(task.id);
const session = this.activeSessions.get(task.id);
session?.dispose();
@@ -178,12 +179,12 @@ export class TaskExecutor {
if (inProgress.length === 0) return;
console.log(`[executor] Found ${inProgress.length} orphaned in-progress task(s)`);
executorLog.log(`Found ${inProgress.length} orphaned in-progress task(s)`);
for (const task of inProgress) {
console.log(`[executor] Resuming ${task.id}: ${task.title || task.description.slice(0, 60)}`);
executorLog.log(`Resuming ${task.id}: ${task.title || task.description.slice(0, 60)}`);
await this.store.logEntry(task.id, "Resumed after engine restart");
this.execute(task).catch((err) =>
console.error(`[executor] Failed to resume ${task.id}:`, err),
executorLog.error(`Failed to resume ${task.id}:`, err),
);
}
}
@@ -227,7 +228,7 @@ export class TaskExecutor {
cwd: worktreePath,
stdio: "pipe",
});
console.log(`[executor] Reused worktree at ${worktreePath}, created branch ${branch}`);
executorLog.log(`Reused worktree at ${worktreePath}, created branch ${branch}`);
}
/**
@@ -244,7 +245,7 @@ export class TaskExecutor {
if (this.executing.has(task.id)) return;
this.executing.add(task.id);
console.log(`[executor] Starting ${task.id}: ${task.title || task.description.slice(0, 60)}`);
executorLog.log(`Starting ${task.id}: ${task.title || task.description.slice(0, 60)}`);
try {
// Check dependencies
@@ -255,7 +256,7 @@ export class TaskExecutor {
});
if (unmetDeps.length > 0) {
console.log(`[executor] ${task.id} blocked by: ${unmetDeps.join(", ")} — deferring`);
executorLog.log(`${task.id} blocked by: ${unmetDeps.join(", ")} — deferring`);
return;
}
@@ -277,7 +278,7 @@ export class TaskExecutor {
this.options.pool.prepareForTask(pooled, branchName);
worktreePath = pooled;
acquiredFromPool = true;
console.log(`[executor] Acquired worktree from pool: ${pooled}`);
executorLog.log(`Acquired worktree from pool: ${pooled}`);
await this.store.updateTask(task.id, { worktree: worktreePath });
await this.store.logEntry(task.id, `Acquired worktree from pool: ${worktreePath}`);
}
@@ -368,12 +369,12 @@ export class TaskExecutor {
if (taskDone) {
await this.store.moveTask(task.id, "in-review");
console.log(`[executor] ✓ ${task.id} completed → in-review`);
executorLog.log(`✓ ${task.id} completed → in-review`);
this.options.onComplete?.(task);
} else {
await this.store.logEntry(task.id, "Agent finished without calling task_done — moved to in-review for inspection");
await this.store.moveTask(task.id, "in-review");
console.log(`[executor] ⚠ ${task.id} finished without task_done → in-review`);
executorLog.log(`⚠ ${task.id} finished without task_done → in-review`);
this.options.onComplete?.(task);
}
} finally {
@@ -391,12 +392,12 @@ export class TaskExecutor {
} catch (err: any) {
if (this.pausedAborted.has(task.id)) {
// Task was paused mid-execution — move to todo, don't mark as failed
console.log(`[executor] ${task.id} paused — moving to todo`);
executorLog.log(`${task.id} paused — moving to todo`);
this.pausedAborted.delete(task.id);
await this.store.logEntry(task.id, "Execution paused — agent terminated, moved to todo");
await this.store.moveTask(task.id, "todo");
} else {
console.error(`[executor] ✗ ${task.id} execution failed:`, err.message);
executorLog.error(`✗ ${task.id} execution failed:`, err.message);
await this.store.logEntry(task.id, `Execution failed: ${err.message}`);
await this.store.updateTask(task.id, { status: "failed" });
this.options.onError?.(task, err);
@@ -529,7 +530,7 @@ export class TaskExecutor {
execute: async (_toolCallId: string, params: Static<typeof reviewStepParams>) => {
const { step, type: reviewType, step_name, baseline } = params;
console.log(`[reviewer] ${taskId}: ${reviewType} review for Step ${step} (${step_name})`);
reviewerLog.log(`${taskId}: ${reviewType} review for Step ${step} (${step_name})`);
await store.logEntry(taskId, `${reviewType} review requested for Step ${step} (${step_name})`);
try {
@@ -549,7 +550,7 @@ export class TaskExecutor {
`${reviewType} review Step ${step}: ${result.verdict}`,
result.summary,
);
console.log(`[reviewer] ${taskId}: Step ${step} ${reviewType} → ${result.verdict}`);
reviewerLog.log(`${taskId}: Step ${step} ${reviewType} → ${result.verdict}`);
let text: string;
switch (result.verdict) {
@@ -561,7 +562,7 @@ export class TaskExecutor {
return { content: [{ type: "text" as const, text }], details: {} };
} catch (err: any) {
console.error(`[reviewer] ${taskId}: review failed: ${err.message}`);
reviewerLog.error(`${taskId}: review failed: ${err.message}`);
await store.logEntry(taskId, `${reviewType} review failed: ${err.message}`);
return {
content: [{ type: "text" as const, text: `UNAVAILABLE — reviewer error: ${err.message}` }],
@@ -576,7 +577,7 @@ export class TaskExecutor {
private createWorktree(branch: string, path: string): void {
if (existsSync(path)) {
console.log(`[executor] Worktree already exists: ${path}`);
executorLog.log(`Worktree already exists: ${path}`);
return;
}
try {
@@ -588,7 +589,7 @@ export class TaskExecutor {
throw new Error(`Failed to create worktree: ${e.message}`);
}
}
console.log(`[executor] Worktree created: ${path}`);
executorLog.log(`Worktree created: ${path}`);
}
/**
@@ -605,15 +606,15 @@ export class TaskExecutor {
// Check if another task still needs this worktree
const otherUser = await findWorktreeUser(this.store, worktreePath, taskId);
if (otherUser) {
console.log(`[executor] Worktree retained for ${taskId} — still needed by ${otherUser}`);
executorLog.log(`Worktree retained for ${taskId} — still needed by ${otherUser}`);
return;
}
try {
execSync(`git worktree remove "${worktreePath}" --force`, { cwd: this.rootDir, stdio: "pipe" });
console.log(`[executor] Cleaned up worktree for ${taskId}`);
executorLog.log(`Cleaned up worktree for ${taskId}`);
} catch (err: any) {
console.error(`[executor] Failed to clean up worktree for ${taskId}:`, err.message);
executorLog.error(`Failed to clean up worktree for ${taskId}:`, err.message);
}
}

1
packages/engine/src/index.ts
View File

@@ -7,3 +7,4 @@ export { aiMergeTask, type MergerOptions } from "./merger.js";
export { reviewStep, type ReviewType, type ReviewVerdict, type ReviewResult, type ReviewOptions } from "./reviewer.js";
export { createHaiAgent, type AgentOptions, type AgentResult } from "./pi.js";
export { WorktreePool } from "./worktree-pool.js";
export { createLogger, type Logger } from "./logger.js";

75
packages/engine/src/logger.test.ts Normal file
View File

@@ -0,0 +1,75 @@
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
import { createLogger, schedulerLog, executorLog, triageLog, mergerLog, worktreePoolLog, reviewerLog } from "./logger.js";
describe("createLogger", () => {
let logSpy: ReturnType<typeof vi.spyOn>;
let warnSpy: ReturnType<typeof vi.spyOn>;
let errorSpy: ReturnType<typeof vi.spyOn>;
beforeEach(() => {
logSpy = vi.spyOn(console, "log").mockImplementation(() => {});
warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
});
afterEach(() => {
logSpy.mockRestore();
warnSpy.mockRestore();
errorSpy.mockRestore();
});
it("formats log output as [prefix] message", () => {
const logger = createLogger("test");
logger.log("hello world");
expect(logSpy).toHaveBeenCalledWith("[test] hello world");
});
it("formats warn output as [prefix] message", () => {
const logger = createLogger("test");
logger.warn("something happened");
expect(warnSpy).toHaveBeenCalledWith("[test] something happened");
});
it("formats error output as [prefix] message", () => {
const logger = createLogger("test");
logger.error("failure");
expect(errorSpy).toHaveBeenCalledWith("[test] failure");
});
it("passes extra arguments through", () => {
const logger = createLogger("test");
const err = new Error("boom");
logger.error("failed:", err);
expect(errorSpy).toHaveBeenCalledWith("[test] failed:", err);
});
it("delegates log to console.log, warn to console.warn, error to console.error", () => {
const logger = createLogger("x");
logger.log("a");
logger.warn("b");
logger.error("c");
expect(logSpy).toHaveBeenCalledTimes(1);
expect(warnSpy).toHaveBeenCalledTimes(1);
expect(errorSpy).toHaveBeenCalledTimes(1);
});
it("pre-built instances use correct prefixes", () => {
schedulerLog.log("tick");
expect(logSpy).toHaveBeenCalledWith("[scheduler] tick");
executorLog.log("run");
expect(logSpy).toHaveBeenCalledWith("[executor] run");
triageLog.log("spec");
expect(logSpy).toHaveBeenCalledWith("[triage] spec");
mergerLog.log("merge");
expect(logSpy).toHaveBeenCalledWith("[merger] merge");
worktreePoolLog.log("prune");
expect(logSpy).toHaveBeenCalledWith("[worktree-pool] prune");
reviewerLog.log("review");
expect(logSpy).toHaveBeenCalledWith("[reviewer] review");
});
});

63
packages/engine/src/logger.ts Normal file
View File

@@ -0,0 +1,63 @@
/**
* Lightweight structured logger for the `@hai/engine` package.
*
* Usage:
* ```ts
* import { createLogger } from "./logger.js";
* const log = createLogger("my-module");
* log.log("hello"); // → console.log("[my-module] hello")
* log.warn("oops"); // → console.warn("[my-module] oops")
* log.error("fail"); // → console.error("[my-module] fail")
* ```
*
* All engine subsystems should use the pre-built instances exported below
* rather than calling `console.*` directly. This gives us a single point
* of control for filtering, suppressing (e.g. in tests), or redirecting
* engine log output in the future.
*/
export interface Logger {
log(message: string, ...args: unknown[]): void;
warn(message: string, ...args: unknown[]): void;
error(message: string, ...args: unknown[]): void;
}
/**
* Create a structured logger that prefixes every message with `[prefix]`.
*
* @param prefix - Short subsystem name, e.g. `"scheduler"` or `"executor"`.
* @returns A `Logger` whose `log`, `warn`, and `error` methods delegate to
* the corresponding `console` method with the prefix prepended.
*/
export function createLogger(prefix: string): Logger {
const tag = `[${prefix}]`;
return {
log(message: string, ...args: unknown[]) {
console.log(`${tag} ${message}`, ...args);
},
warn(message: string, ...args: unknown[]) {
console.warn(`${tag} ${message}`, ...args);
},
error(message: string, ...args: unknown[]) {
console.error(`${tag} ${message}`, ...args);
},
};
}
/** Logger for the scheduler subsystem. */
export const schedulerLog = createLogger("scheduler");
/** Logger for the task executor subsystem. */
export const executorLog = createLogger("executor");
/** Logger for the triage processor subsystem. */
export const triageLog = createLogger("triage");
/** Logger for the merge/auto-merge subsystem. */
export const mergerLog = createLogger("merger");
/** Logger for the worktree pool subsystem. */
export const worktreePoolLog = createLogger("worktree-pool");
/** Logger for the review subsystem. */
export const reviewerLog = createLogger("reviewer");

13
packages/engine/src/merger.ts
View File

@@ -4,6 +4,7 @@ import type { TaskStore, Task, MergeResult } from "@hai/core";
import { createHaiAgent } from "./pi.js";
import type { WorktreePool } from "./worktree-pool.js";
import { AgentLogger } from "./agent-logger.js";
import { mergerLog } from "./logger.js";
/**
* Build the merge system prompt. When `includeTaskId` is true (default),
@@ -140,7 +141,7 @@ export async function aiMergeTask(
};
if (!worktreePath) {
console.warn(`[merger] ${taskId}: no worktree path set — skipping worktree cleanup`);
mergerLog.warn(`${taskId}: no worktree path set — skipping worktree cleanup`);
}
// 2. Read settings early (reused later for recycleWorktrees)
@@ -215,9 +216,7 @@ export async function aiMergeTask(
// 5. Spawn pi agent to resolve conflicts (if any) and write commit message
await store.updateTask(taskId, { status: "merging" });
console.log(
`[merger] ${taskId}: ${hasConflicts ? "resolving conflicts + " : ""}writing commit message`,
);
mergerLog.log(`${taskId}: ${hasConflicts ? "resolving conflicts + " : ""}writing commit message`);
const agentLogger = new AgentLogger({
store,
@@ -253,7 +252,7 @@ export async function aiMergeTask(
}).trim();
if (staged !== "0") {
console.log("[merger] Agent didn't commit — committing with fallback message");
mergerLog.log("Agent didn't commit — committing with fallback message");
const escapedLog = commitLog.replace(/"/g, '\\"');
const fallbackPrefix = includeTaskId ? `feat(${taskId})` : "feat";
execSync(
@@ -265,7 +264,7 @@ export async function aiMergeTask(
result.merged = true;
} catch (err: any) {
// Agent failed — try to abort the merge
console.error(`[merger] Agent failed: ${err.message}`);
mergerLog.error(`Agent failed: ${err.message}`);
try {
execSync("git reset --merge", { cwd: rootDir, stdio: "pipe" });
} catch { /* */ }
@@ -290,7 +289,7 @@ export async function aiMergeTask(
if (worktreePath && existsSync(worktreePath)) {
const otherUser = await findWorktreeUser(store, worktreePath, taskId);
if (otherUser) {
console.log(`[merger] Worktree retained — still needed by ${otherUser}`);
mergerLog.log(`Worktree retained — still needed by ${otherUser}`);
result.worktreeRemoved = false;
} else if (options.pool && settings.recycleWorktrees) {
options.pool.release(worktreePath);

19
packages/engine/src/scheduler.ts
View File

@@ -1,5 +1,6 @@
import { resolveDependencyOrder, type TaskStore, type Task } from "@hai/core";
import type { AgentSemaphore } from "./concurrency.js";
import { schedulerLog } from "./logger.js";
/**
* Check whether two sets of file scope paths overlap.
@@ -91,9 +92,7 @@ export class Scheduler {
this.activePollMs = interval;
this.pollInterval = setInterval(() => this.schedule(), interval);
this.schedule();
console.log(
`[scheduler] Started (poll interval: ${interval}ms)`,
);
schedulerLog.log(`Started (poll interval: ${interval}ms)`);
}
stop(): void {
@@ -103,7 +102,7 @@ export class Scheduler {
this.pollInterval = null;
this.activePollMs = null;
}
console.log("[scheduler] Stopped");
schedulerLog.log("Stopped");
}
/**
@@ -119,7 +118,7 @@ export class Scheduler {
}
this.activePollMs = newIntervalMs;
this.pollInterval = setInterval(() => this.schedule(), newIntervalMs);
console.log(`[scheduler] Poll interval updated to ${newIntervalMs}ms`);
schedulerLog.log(`Poll interval updated to ${newIntervalMs}ms`);
}
/**
@@ -162,9 +161,7 @@ export class Scheduler {
if (activeWorktrees >= maxWorktrees) {
if (!this.wasWorktreeLimited) {
console.log(
`[scheduler] Worktree limit reached (${activeWorktrees}/${maxWorktrees})`,
);
schedulerLog.log(`Worktree limit reached (${activeWorktrees}/${maxWorktrees})`);
this.wasWorktreeLimited = true;
}
return;
@@ -262,9 +259,7 @@ export class Scheduler {
}
// Dependencies met — clear status and move to in-progress
console.log(
`[scheduler] Starting ${task.id}: ${task.title || task.id} (deps satisfied)`,
);
schedulerLog.log(`Starting ${task.id}: ${task.title || task.id} (deps satisfied)`);
await this.store.updateTask(task.id, { status: null, blockedBy: null });
await this.store.moveTask(task.id, "in-progress");
this.options.onSchedule?.(task);
@@ -277,7 +272,7 @@ export class Scheduler {
}
}
} catch (err) {
console.error("[scheduler] Scheduling error:", err);
schedulerLog.error("Scheduling error:", err);
} finally {
this.scheduling = false;
}

21
packages/engine/src/triage.ts
View File

@@ -5,6 +5,7 @@ import type { ToolDefinition } from "@mariozechner/pi-coding-agent";
import { createHaiAgent } from "./pi.js";
import type { AgentSemaphore } from "./concurrency.js";
import { AgentLogger } from "./agent-logger.js";
import { triageLog } from "./logger.js";
const TRIAGE_SYSTEM_PROMPT = `You are a task specification agent for "hai", an AI-orchestrated task board.
@@ -188,7 +189,7 @@ export class TriageProcessor {
this.activePollMs = interval;
this.pollInterval = setInterval(() => this.poll(), interval);
this.poll();
console.log("[triage] Processor started");
triageLog.log("Processor started");
}
stop(): void {
@@ -198,7 +199,7 @@ export class TriageProcessor {
this.pollInterval = null;
this.activePollMs = null;
}
console.log("[triage] Processor stopped");
triageLog.log("Processor stopped");
}
/**
@@ -214,7 +215,7 @@ export class TriageProcessor {
}
this.activePollMs = newIntervalMs;
this.pollInterval = setInterval(() => this.poll(), newIntervalMs);
console.log(`[triage] Poll interval updated to ${newIntervalMs}ms`);
triageLog.log(`Poll interval updated to ${newIntervalMs}ms`);
}
private async poll(): Promise<void> {
@@ -233,7 +234,7 @@ export class TriageProcessor {
await this.specifyTask(task);
}
} catch (err) {
console.error("[triage] Poll error:", err);
triageLog.error("Poll error:", err);
}
}
@@ -241,7 +242,7 @@ export class TriageProcessor {
if (this.processing.has(task.id)) return;
this.processing.add(task.id);
console.log(`[triage] Specifying ${task.id}: ${task.title || task.description.slice(0, 60)}`);
triageLog.log(`Specifying ${task.id}: ${task.title || task.description.slice(0, 60)}`);
this.options.onSpecifyStart?.(task);
try {
@@ -259,7 +260,7 @@ export class TriageProcessor {
? (id, delta) => this.options.onAgentText!(id, delta)
: undefined,
onAgentTool: (_id, name) => {
console.log(`[triage] ${task.id} tool: ${name}`);
triageLog.log(`${task.id} tool: ${name}`);
},
});
@@ -293,13 +294,13 @@ export class TriageProcessor {
if (dupMatch) {
const dupId = dupMatch[1];
console.log(`[triage] ${task.id} is a duplicate of ${dupId} — closing`);
triageLog.log(`${task.id} is a duplicate of ${dupId} — closing`);
await this.store.logEntry(task.id, `Duplicate of ${dupId} — closed`);
await this.store.deleteTask(task.id);
} else {
await this.store.updateTask(task.id, { status: null });
await this.store.moveTask(task.id, "todo");
console.log(`[triage] ✓ ${task.id} specified and moved to todo`);
triageLog.log(`✓ ${task.id} specified and moved to todo`);
this.options.onSpecifyComplete?.(task);
}
} finally {
@@ -317,10 +318,10 @@ export class TriageProcessor {
// Race condition: task was deleted (e.g. as a duplicate) between listTasks()
// and specifyTask(). The file is gone, so just log and skip — no point retrying.
if (err.code === "ENOENT") {
console.log(`[triage] ${task.id} no longer exists — skipping`);
triageLog.log(`${task.id} no longer exists — skipping`);
} else {
await this.store.updateTask(task.id, { status: null }).catch(() => {});
console.error(`[triage] ✗ ${task.id} specification failed:`, err.message);
triageLog.error(`✗ ${task.id} specification failed:`, err.message);
this.options.onSpecifyError?.(task, err);
}
} finally {

3
packages/engine/src/worktree-pool.ts
View File

@@ -1,5 +1,6 @@
import { execSync } from "node:child_process";
import { existsSync } from "node:fs";
import { worktreePoolLog } from "./logger.js";
/**
* A pool of idle git worktrees that can be recycled across tasks.
@@ -28,7 +29,7 @@ export class WorktreePool {
if (existsSync(path)) {
return path;
}
console.log(`[worktree-pool] Pruned stale entry: ${path}`);
worktreePoolLog.log(`Pruned stale entry: ${path}`);
}
return null;
}