fix: correct default terminal ports, deduplicate API log parsing, fix test lint

- dashboard-manager.ts: fix NEXT_PUBLIC_TERMINAL_PORT defaults from 3001/3003
  to 14800/14801 to match the canonical defaults in web-dir.ts
- log-reader.ts: extract ApiLogEntry type and parseApiLogs() function to core
  so CLI and web packages share one implementation instead of two
- perf-utils.ts: loadRequests() delegates to core parseApiLogs() (no more
  duplicated parsing loop)
- perf-utils.test.ts: update mock to include parseApiLogs delegating to
  mockReadLogsFromDir; add sessionId to toEqual expectation
- client-logger.test.ts: remove useless constructor from ThrowingObserver class
- request-logger.test.ts: replace forbidden typeof import() type annotations
  with proper import type at the top of the file

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
This commit is contained in:
Prateek 2026-02-19 06:59:43 +05:30
parent fe4d50973d
commit f9fbe92cda
14 changed files with 6580 additions and 46 deletions

View File

@ -10,6 +10,33 @@ vi.mock("@composio/ao-core", () => ({
loadConfig: mockLoadConfig,
resolveProjectLogDir: mockResolveProjectLogDir,
readLogsFromDir: mockReadLogsFromDir,
// parseApiLogs delegates to mockReadLogsFromDir so tests can control entries
parseApiLogs: (logDir: string, opts?: { since?: Date; route?: string }) => {
const entries = (mockReadLogsFromDir(logDir, "api", { source: "api", since: opts?.since }) ?? []) as Array<{
ts: string;
sessionId: string | null;
data?: Record<string, unknown>;
}>;
const results = [];
for (const entry of entries) {
const data = entry.data ?? {};
if (!data["method"] || !data["path"]) continue;
const req = {
ts: entry.ts,
method: String(data["method"]),
path: String(data["path"]),
sessionId: entry.sessionId,
statusCode: Number(data["statusCode"]) || 0,
durationMs: Number(data["durationMs"]) || 0,
error: data["error"] ? String(data["error"]) : undefined,
timings: data["timings"] as Record<string, number> | undefined,
cacheStats: data["cacheStats"] as { hits: number; misses: number; hitRate: number; size: number } | undefined,
};
if (opts?.route && !req.path.includes(opts.route)) continue;
results.push(req);
}
return results;
},
}));
import { resolveLogDir, loadRequests, type ParsedRequest } from "../../src/lib/perf-utils.js";
@ -65,6 +92,7 @@ describe("loadRequests", () => {
ts: "2025-01-01T00:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 45,
error: undefined,

View File

@ -3,18 +3,8 @@
* Used by `ao perf` and potentially other CLI commands that read API logs.
*/
import { loadConfig, resolveProjectLogDir, readLogsFromDir } from "@composio/ao-core";
export interface ParsedRequest {
ts: string;
method: string;
path: string;
statusCode: number;
durationMs: number;
error?: string;
timings?: Record<string, number>;
cacheStats?: { hits: number; misses: number; hitRate: number; size: number };
}
import { loadConfig, resolveProjectLogDir, parseApiLogs } from "@composio/ao-core";
export type { ApiLogEntry as ParsedRequest } from "@composio/ao-core";
/** Resolve the log directory from config. Throws if no projects configured. */
export function resolveLogDir(): string {
@ -25,31 +15,6 @@ export function resolveLogDir(): string {
}
/** Parse API log entries into typed request objects. */
export function loadRequests(logDir: string, opts?: { since?: Date; route?: string }): ParsedRequest[] {
const entries = readLogsFromDir(logDir, "api", {
source: "api",
since: opts?.since,
});
const requests: ParsedRequest[] = [];
for (const entry of entries) {
const data = entry.data ?? {};
if (!data["method"] || !data["path"]) continue;
const req: ParsedRequest = {
ts: entry.ts,
method: String(data["method"]),
path: String(data["path"]),
statusCode: Number(data["statusCode"]) || 0,
durationMs: Number(data["durationMs"]) || 0,
error: data["error"] ? String(data["error"]) : undefined,
timings: data["timings"] as Record<string, number> | undefined,
cacheStats: data["cacheStats"] as ParsedRequest["cacheStats"] | undefined,
};
if (opts?.route && !req.path.includes(opts.route)) continue;
requests.push(req);
}
return requests;
export function loadRequests(logDir: string, opts?: { since?: Date; route?: string }) {
return parseApiLogs(logDir, opts);
}

View File

@ -0,0 +1,967 @@
import { describe, it, expect, beforeEach, afterEach, vi } from "vitest";
import type { ChildProcess } from "node:child_process";
import type { DashboardRestartOpts } from "../dashboard-manager.js";
// ---------------------------------------------------------------------------
// Hoisted mock functions — vi.hoisted() runs before vi.mock factories
// ---------------------------------------------------------------------------
const {
mockExecFile,
mockSpawn,
mockExistsSync,
mockReadFileSync,
mockWriteFileSync,
mockUnlinkSync,
mockRmSync,
mockMkdirSync,
mockOpenSync,
mockCloseSync,
mockFetch,
} = vi.hoisted(() => ({
mockExecFile: vi.fn(),
mockSpawn: vi.fn(),
mockExistsSync: vi.fn(),
mockReadFileSync: vi.fn(),
mockWriteFileSync: vi.fn(),
mockUnlinkSync: vi.fn(),
mockRmSync: vi.fn(),
mockMkdirSync: vi.fn(),
mockOpenSync: vi.fn(),
mockCloseSync: vi.fn(),
mockFetch: vi.fn(),
}));
// ---------------------------------------------------------------------------
// Mock node:child_process
// ---------------------------------------------------------------------------
vi.mock("node:child_process", () => ({
execFile: mockExecFile,
spawn: mockSpawn,
}));
// ---------------------------------------------------------------------------
// Mock node:fs
// ---------------------------------------------------------------------------
vi.mock("node:fs", () => ({
existsSync: mockExistsSync,
readFileSync: mockReadFileSync,
writeFileSync: mockWriteFileSync,
unlinkSync: mockUnlinkSync,
rmSync: mockRmSync,
mkdirSync: mockMkdirSync,
openSync: mockOpenSync,
closeSync: mockCloseSync,
}));
// ---------------------------------------------------------------------------
// Mock node:util — promisify wraps our mock execFile as a promise-returning fn
// ---------------------------------------------------------------------------
vi.mock("node:util", () => ({
promisify: (fn: unknown) => {
if (fn === mockExecFile) {
return (...args: unknown[]) => {
return new Promise((resolve, reject) => {
(fn as Function)(...args, (err: Error | null, stdout: string, stderr: string) => {
if (err) reject(err);
else resolve({ stdout, stderr });
});
});
};
}
throw new Error("promisify called with unexpected function");
},
}));
// ---------------------------------------------------------------------------
// Mock global fetch for waitForHealthy
// ---------------------------------------------------------------------------
vi.stubGlobal("fetch", mockFetch);
// ---------------------------------------------------------------------------
// Import the module under test (after all mocks are wired)
// ---------------------------------------------------------------------------
import {
readPidFile,
writePidFile,
removePidFile,
waitForHealthy,
getDashboardStatus,
stopDashboard,
restartDashboard,
} from "../dashboard-manager.js";
// ---------------------------------------------------------------------------
// Helpers
// ---------------------------------------------------------------------------
/** Simulate a successful `lsof` call returning a PID. */
function mockLsofReturnsPid(pid: number): void {
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
cb(null, `${pid}\n`, "");
} else {
cb(new Error("unknown command"), "", "");
}
},
);
}
/** Simulate `lsof` finding nothing (exit code 1). */
function mockLsofReturnsEmpty(): void {
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
cb(new Error("exit code 1"), "", "");
} else {
cb(new Error("unknown command"), "", "");
}
},
);
}
/** Create a fake ChildProcess-like object from spawn. */
function makeFakeChild(pid: number | undefined): Partial<ChildProcess> {
return {
pid,
unref: vi.fn(),
};
}
beforeEach(() => {
vi.restoreAllMocks();
// Reset all mocks individually so implementations are cleared
mockExecFile.mockReset();
mockSpawn.mockReset();
mockExistsSync.mockReset();
mockReadFileSync.mockReset();
mockWriteFileSync.mockReset();
mockUnlinkSync.mockReset();
mockRmSync.mockReset();
mockMkdirSync.mockReset();
mockOpenSync.mockReset();
mockCloseSync.mockReset();
mockFetch.mockReset();
});
afterEach(() => {
vi.useRealTimers();
});
// =========================================================================
// readPidFile
// =========================================================================
describe("readPidFile", () => {
it("returns null when PID file does not exist", () => {
mockExistsSync.mockReturnValue(false);
expect(readPidFile("/tmp/logs")).toBeNull();
expect(mockExistsSync).toHaveBeenCalledWith("/tmp/logs/dashboard.pid");
});
it("returns PID when file exists and process is alive", () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("42\n");
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => true);
const result = readPidFile("/tmp/logs");
expect(result).toBe(42);
expect(killSpy).toHaveBeenCalledWith(42, 0);
});
it("returns null and cleans up when PID file contains NaN", () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("not-a-number\n");
const result = readPidFile("/tmp/logs");
expect(result).toBeNull();
});
it("returns null and removes stale PID file when process is dead", () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("99999\n");
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => {
throw new Error("ESRCH");
});
const result = readPidFile("/tmp/logs");
expect(result).toBeNull();
expect(killSpy).toHaveBeenCalledWith(99999, 0);
// Should attempt to remove the stale PID file
expect(mockUnlinkSync).toHaveBeenCalledWith("/tmp/logs/dashboard.pid");
});
it("handles unlink failure gracefully when cleaning stale PID", () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("99999\n");
vi.spyOn(process, "kill").mockImplementation(() => {
throw new Error("ESRCH");
});
mockUnlinkSync.mockImplementation(() => {
throw new Error("EACCES");
});
// Should not throw even if unlink fails
expect(() => readPidFile("/tmp/logs")).not.toThrow();
expect(readPidFile("/tmp/logs")).toBeNull();
});
});
// =========================================================================
// writePidFile
// =========================================================================
describe("writePidFile", () => {
it("writes the PID as a string to the correct path", () => {
writePidFile("/tmp/logs", 1234);
expect(mockWriteFileSync).toHaveBeenCalledWith(
"/tmp/logs/dashboard.pid",
"1234",
"utf-8",
);
});
it("handles large PIDs", () => {
writePidFile("/var/ao", 4294967295);
expect(mockWriteFileSync).toHaveBeenCalledWith(
"/var/ao/dashboard.pid",
"4294967295",
"utf-8",
);
});
});
// =========================================================================
// removePidFile
// =========================================================================
describe("removePidFile", () => {
it("removes the PID file when it exists", () => {
mockExistsSync.mockReturnValue(true);
removePidFile("/tmp/logs");
expect(mockUnlinkSync).toHaveBeenCalledWith("/tmp/logs/dashboard.pid");
});
it("does nothing when PID file does not exist", () => {
mockExistsSync.mockReturnValue(false);
removePidFile("/tmp/logs");
expect(mockUnlinkSync).not.toHaveBeenCalled();
});
it("does not throw when unlink fails", () => {
mockExistsSync.mockReturnValue(true);
mockUnlinkSync.mockImplementation(() => {
throw new Error("EACCES");
});
expect(() => removePidFile("/tmp/logs")).not.toThrow();
});
it("does not throw when existsSync fails", () => {
mockExistsSync.mockImplementation(() => {
throw new Error("ENOENT");
});
expect(() => removePidFile("/tmp/logs")).not.toThrow();
});
});
// =========================================================================
// waitForHealthy
// =========================================================================
describe("waitForHealthy", () => {
it("returns true when fetch succeeds with 200", async () => {
mockFetch.mockResolvedValue({ ok: true, status: 200 });
const result = await waitForHealthy(3000, 5000);
expect(result).toBe(true);
expect(mockFetch).toHaveBeenCalledWith(
"http://localhost:3000",
expect.objectContaining({ signal: expect.any(AbortSignal) }),
);
});
it("returns true when server responds with 404", async () => {
mockFetch.mockResolvedValue({ ok: false, status: 404 });
const result = await waitForHealthy(3000, 5000);
expect(result).toBe(true);
});
it("returns false on timeout when fetch keeps failing", async () => {
vi.useFakeTimers();
mockFetch.mockRejectedValue(new Error("ECONNREFUSED"));
const resultPromise = waitForHealthy(3000, 3000);
// The function polls every 1000ms. Advance past the deadline.
// First attempt: immediate, fails -> waits 1000ms
await vi.advanceTimersByTimeAsync(1000);
// Second attempt: fails -> waits 1000ms
await vi.advanceTimersByTimeAsync(1000);
// Third attempt: fails -> waits 1000ms
await vi.advanceTimersByTimeAsync(1000);
// Past deadline, should exit loop
await vi.advanceTimersByTimeAsync(1000);
const result = await resultPromise;
expect(result).toBe(false);
});
it("succeeds after initial failures when server eventually responds", async () => {
vi.useFakeTimers();
let callCount = 0;
mockFetch.mockImplementation(() => {
callCount++;
if (callCount < 3) {
return Promise.reject(new Error("ECONNREFUSED"));
}
return Promise.resolve({ ok: true, status: 200 });
});
const resultPromise = waitForHealthy(3000, 10_000);
// First call fails immediately, then waits 1000ms
await vi.advanceTimersByTimeAsync(1000);
// Second call fails, waits 1000ms
await vi.advanceTimersByTimeAsync(1000);
// Third call succeeds (callCount === 3)
await vi.advanceTimersByTimeAsync(1000);
const result = await resultPromise;
expect(result).toBe(true);
});
it("handles 500 server error (not ok, not 404) and retries", async () => {
vi.useFakeTimers();
let callCount = 0;
mockFetch.mockImplementation(() => {
callCount++;
if (callCount === 1) {
// Server error — not ok and not 404
return Promise.resolve({ ok: false, status: 500 });
}
return Promise.resolve({ ok: true, status: 200 });
});
const resultPromise = waitForHealthy(3000, 10_000);
// First attempt returns 500, but res.ok is false and status != 404, so no early return.
// Wait for poll interval
await vi.advanceTimersByTimeAsync(1000);
// Second attempt returns 200
await vi.advanceTimersByTimeAsync(1000);
const result = await resultPromise;
expect(result).toBe(true);
});
it("uses default timeout of 30000ms", async () => {
vi.useFakeTimers();
mockFetch.mockRejectedValue(new Error("ECONNREFUSED"));
const resultPromise = waitForHealthy(3000);
// Advance 30 seconds + a bit to exceed the deadline
for (let i = 0; i < 32; i++) {
await vi.advanceTimersByTimeAsync(1000);
}
const result = await resultPromise;
expect(result).toBe(false);
});
});
// =========================================================================
// getDashboardStatus
// =========================================================================
describe("getDashboardStatus", () => {
it('returns pid_file source when PID file has a live process', async () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("1234\n");
vi.spyOn(process, "kill").mockImplementation(() => true);
mockLsofReturnsEmpty(); // port scan would find nothing
const status = await getDashboardStatus("/tmp/logs", 3000);
expect(status).toEqual({ running: true, pid: 1234, source: "pid_file" });
});
it('returns port_scan source when no PID file but port is occupied', async () => {
// PID file does not exist
mockExistsSync.mockReturnValue(false);
// lsof finds a process on the port
mockLsofReturnsPid(5678);
const status = await getDashboardStatus("/tmp/logs", 3000);
expect(status).toEqual({ running: true, pid: 5678, source: "port_scan" });
});
it("returns not running when neither PID file nor port scan finds a process", async () => {
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
const status = await getDashboardStatus("/tmp/logs", 3000);
expect(status).toEqual({ running: false, pid: null, source: null });
});
it("prefers PID file over port scan when both would find a process", async () => {
// PID file exists and is alive
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("1111\n");
vi.spyOn(process, "kill").mockImplementation(() => true);
// Port scan would also find something
mockLsofReturnsPid(2222);
const status = await getDashboardStatus("/tmp/logs", 3000);
// Should return the PID from the file, not from port scan
expect(status).toEqual({ running: true, pid: 1111, source: "pid_file" });
});
it("falls back to port scan when PID file has stale process", async () => {
// First call to existsSync (in readPidFile) returns true for PID file
// but process.kill throws (stale PID)
mockExistsSync.mockImplementation((path: string) => {
return (path as string).endsWith("dashboard.pid");
});
mockReadFileSync.mockReturnValue("9999\n");
vi.spyOn(process, "kill").mockImplementation(() => {
throw new Error("ESRCH");
});
mockLsofReturnsPid(5555);
const status = await getDashboardStatus("/tmp/logs", 3000);
// readPidFile returns null (stale), falls through to port scan
expect(status).toEqual({ running: true, pid: 5555, source: "port_scan" });
});
});
// =========================================================================
// stopDashboard
// =========================================================================
describe("stopDashboard", () => {
it("returns false when no process is found", async () => {
// No PID file
mockExistsSync.mockReturnValue(false);
// No process on port
mockLsofReturnsEmpty();
const result = await stopDashboard("/tmp/logs", 3000);
expect(result).toBe(false);
});
it("kills process found via PID file and returns true", async () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("1234\n");
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => true);
// After kill, lsof should find nothing (port released)
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
// First call in findPidOnPort from stopDashboard returns the PID,
// subsequent calls from waitForPortFree return nothing (port freed)
if (lsofCallCount <= 1) {
cb(null, "1234\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
const result = await stopDashboard("/tmp/logs", 3000);
expect(result).toBe(true);
// Check that SIGTERM was sent (call 0 is the kill(pid,0) check, call 1 is SIGTERM)
expect(killSpy).toHaveBeenCalledWith(1234, "SIGTERM");
});
it("kills process found via port scan when no PID file", async () => {
mockExistsSync.mockReturnValue(false);
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
// First call finds the PID, second call in waitForPortFree finds nothing
if (lsofCallCount <= 1) {
cb(null, "5678\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => true);
const result = await stopDashboard("/tmp/logs", 3000);
expect(result).toBe(true);
expect(killSpy).toHaveBeenCalledWith(5678, "SIGTERM");
});
it("handles process already exited when sending SIGTERM", async () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("1234\n");
let killCallCount = 0;
vi.spyOn(process, "kill").mockImplementation((...args: unknown[]) => {
killCallCount++;
if (killCallCount === 1) {
// kill(pid, 0) — alive check succeeds
return true;
}
// kill(pid, SIGTERM) — process already gone
throw new Error("ESRCH");
});
// Port is already free (process already exited)
mockLsofReturnsEmpty();
const result = await stopDashboard("/tmp/logs", 3000);
expect(result).toBe(true);
});
it("removes PID file after stopping", async () => {
mockExistsSync.mockReturnValue(true);
mockReadFileSync.mockReturnValue("1234\n");
vi.spyOn(process, "kill").mockImplementation(() => true);
mockLsofReturnsEmpty();
await stopDashboard("/tmp/logs", 3000);
// removePidFile checks existsSync and calls unlinkSync
expect(mockUnlinkSync).toHaveBeenCalled();
});
});
// =========================================================================
// restartDashboard
// =========================================================================
describe("restartDashboard", () => {
function makeOpts(overrides: Partial<DashboardRestartOpts> = {}): DashboardRestartOpts {
return {
webDir: "/app/packages/web",
logDir: "/tmp/ao-logs",
...overrides,
};
}
/** Set up mocks for a fresh start (no existing process). */
function setupFreshStart(spawnPid: number = 12345): void {
// No PID file
mockExistsSync.mockReturnValue(false);
// No process on port
mockLsofReturnsEmpty();
// openSync returns file descriptors
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
// spawn returns a child with a PID
mockSpawn.mockReturnValue(makeFakeChild(spawnPid));
}
it("spawns a new process when no existing process is running", async () => {
setupFreshStart(42);
const result = await restartDashboard(makeOpts());
expect(result).toEqual({ pid: 42, killed: false, cleaned: false });
expect(mockSpawn).toHaveBeenCalledWith(
"npx",
["next", "dev", "-p", "3000"],
expect.objectContaining({
cwd: "/app/packages/web",
detached: true,
}),
);
});
it("uses specified port instead of default 3000", async () => {
setupFreshStart(100);
const result = await restartDashboard(makeOpts({ port: 8080 }));
expect(result.pid).toBe(100);
expect(mockSpawn).toHaveBeenCalledWith(
"npx",
["next", "dev", "-p", "8080"],
expect.objectContaining({
cwd: "/app/packages/web",
}),
);
});
it("kills existing process found via PID file", async () => {
// PID file says process 999 is running
const existsSyncImpl = (path: string) => {
if ((path as string).endsWith("dashboard.pid")) return true;
if ((path as string).endsWith(".next")) return false;
return false;
};
mockExistsSync.mockImplementation(existsSyncImpl);
mockReadFileSync.mockReturnValue("999\n");
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => true);
// lsof: first call for initial findPidOnPort (in restartDashboard),
// subsequent calls for waitForPortFree should find nothing
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
if (lsofCallCount <= 1) {
cb(null, "999\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(1000));
const result = await restartDashboard(makeOpts());
expect(result.killed).toBe(true);
expect(killSpy).toHaveBeenCalledWith(999, "SIGTERM");
});
it("kills existing process found via port scan when no PID file", async () => {
mockExistsSync.mockImplementation((path: string) => {
if ((path as string).endsWith("dashboard.pid")) return false;
return false;
});
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
if (lsofCallCount <= 1) {
cb(null, "888\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
const killSpy = vi.spyOn(process, "kill").mockImplementation(() => true);
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(2000));
const result = await restartDashboard(makeOpts());
expect(result.killed).toBe(true);
expect(killSpy).toHaveBeenCalledWith(888, "SIGTERM");
expect(result.pid).toBe(2000);
});
it("cleans .next directory when clean: true and .next exists", async () => {
mockExistsSync.mockImplementation((path: string) => {
if ((path as string).endsWith("dashboard.pid")) return false;
if ((path as string).endsWith(".next")) return true;
// logDir exists
return true;
});
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(500));
const result = await restartDashboard(makeOpts({ clean: true }));
expect(result.cleaned).toBe(true);
expect(mockRmSync).toHaveBeenCalledWith(
expect.stringContaining(".next"),
{ recursive: true, force: true },
);
});
it("does not clean when clean: true but .next does not exist", async () => {
// All existsSync calls return false (no PID, no .next)
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(500));
const result = await restartDashboard(makeOpts({ clean: true }));
expect(result.cleaned).toBe(false);
expect(mockRmSync).not.toHaveBeenCalled();
});
it("does not clean when clean option is not set", async () => {
setupFreshStart(500);
const result = await restartDashboard(makeOpts());
expect(result.cleaned).toBe(false);
expect(mockRmSync).not.toHaveBeenCalled();
});
it("creates log directory if it does not exist", async () => {
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(123));
await restartDashboard(makeOpts({ logDir: "/new/logs" }));
expect(mockMkdirSync).toHaveBeenCalledWith("/new/logs", { recursive: true });
});
it("opens log files for stdout and stderr", async () => {
setupFreshStart(123);
await restartDashboard(makeOpts({ logDir: "/tmp/ao-logs" }));
expect(mockOpenSync).toHaveBeenCalledWith("/tmp/ao-logs/dashboard.out.log", "a");
expect(mockOpenSync).toHaveBeenCalledWith("/tmp/ao-logs/dashboard.err.log", "a");
});
it("closes file descriptors after spawn", async () => {
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(42).mockReturnValueOnce(43);
mockSpawn.mockReturnValue(makeFakeChild(100));
await restartDashboard(makeOpts());
expect(mockCloseSync).toHaveBeenCalledWith(42);
expect(mockCloseSync).toHaveBeenCalledWith(43);
});
it("unrefs the child process so parent can exit", async () => {
setupFreshStart(100);
const fakeChild = makeFakeChild(100);
mockSpawn.mockReturnValue(fakeChild);
await restartDashboard(makeOpts());
expect(fakeChild.unref).toHaveBeenCalled();
});
it("writes PID file after successful spawn", async () => {
setupFreshStart(7777);
await restartDashboard(makeOpts({ logDir: "/tmp/ao-logs" }));
expect(mockWriteFileSync).toHaveBeenCalledWith(
"/tmp/ao-logs/dashboard.pid",
"7777",
"utf-8",
);
});
it("does not write PID file when spawn returns no PID", async () => {
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(undefined));
const result = await restartDashboard(makeOpts());
expect(result.pid).toBeNull();
expect(mockWriteFileSync).not.toHaveBeenCalled();
});
it("calls onStatus with progress messages for fresh start", async () => {
setupFreshStart(555);
const messages: string[] = [];
await restartDashboard(
makeOpts({ onStatus: (msg) => messages.push(msg) }),
);
// Fresh start: only "Dashboard started" message
expect(messages.some((m) => m.includes("Dashboard started"))).toBe(true);
expect(messages.some((m) => m.includes("555"))).toBe(true);
});
it("calls onStatus with stop and start messages when killing existing", async () => {
mockExistsSync.mockImplementation((path: string) => {
if ((path as string).endsWith("dashboard.pid")) return true;
return false;
});
mockReadFileSync.mockReturnValue("100\n");
vi.spyOn(process, "kill").mockImplementation(() => true);
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
if (lsofCallCount <= 1) {
cb(null, "100\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(200));
const messages: string[] = [];
await restartDashboard(
makeOpts({ onStatus: (msg) => messages.push(msg) }),
);
expect(messages.some((m) => m.includes("Stopping"))).toBe(true);
expect(messages.some((m) => m.includes("stopped"))).toBe(true);
expect(messages.some((m) => m.includes("started"))).toBe(true);
});
it("calls onStatus with clean messages when cleaning", async () => {
mockExistsSync.mockImplementation((path: string) => {
if ((path as string).endsWith("dashboard.pid")) return false;
if ((path as string).endsWith(".next")) return true;
return true;
});
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(300));
const messages: string[] = [];
await restartDashboard(
makeOpts({ clean: true, onStatus: (msg) => messages.push(msg) }),
);
expect(messages.some((m) => m.includes("Cleaning"))).toBe(true);
expect(messages.some((m) => m.includes("cleaned"))).toBe(true);
});
it("passes AO_CONFIG_PATH to the spawned process env", async () => {
setupFreshStart(100);
await restartDashboard(
makeOpts({ configPath: "/path/to/config.yaml" }),
);
const spawnCall = mockSpawn.mock.calls[0];
const spawnOpts = spawnCall[2];
expect(spawnOpts.env["AO_CONFIG_PATH"]).toBe("/path/to/config.yaml");
});
it("sets PORT in spawned process env", async () => {
setupFreshStart(100);
await restartDashboard(makeOpts({ port: 9999 }));
const spawnCall = mockSpawn.mock.calls[0];
const spawnOpts = spawnCall[2];
expect(spawnOpts.env["PORT"]).toBe("9999");
});
it("spawns process with stdio pointing to file descriptors", async () => {
mockExistsSync.mockReturnValue(false);
mockLsofReturnsEmpty();
mockOpenSync.mockReturnValueOnce(77).mockReturnValueOnce(88);
mockSpawn.mockReturnValue(makeFakeChild(100));
await restartDashboard(makeOpts());
const spawnCall = mockSpawn.mock.calls[0];
const spawnOpts = spawnCall[2];
expect(spawnOpts.stdio).toEqual(["ignore", 77, 88]);
});
it("returns full result with killed, cleaned, and pid", async () => {
// Existing process to kill
mockExistsSync.mockImplementation((path: string) => {
if ((path as string).endsWith("dashboard.pid")) return true;
if ((path as string).endsWith(".next")) return true;
return true;
});
mockReadFileSync.mockReturnValue("111\n");
vi.spyOn(process, "kill").mockImplementation(() => true);
let lsofCallCount = 0;
mockExecFile.mockImplementation(
(
cmd: string,
_args: string[],
_opts: unknown,
cb: (err: Error | null, stdout: string, stderr: string) => void,
) => {
if (cmd === "lsof") {
lsofCallCount++;
if (lsofCallCount <= 1) {
cb(null, "111\n", "");
} else {
cb(new Error("exit code 1"), "", "");
}
}
},
);
mockOpenSync.mockReturnValueOnce(10).mockReturnValueOnce(11);
mockSpawn.mockReturnValue(makeFakeChild(222));
const result = await restartDashboard(
makeOpts({ clean: true }),
);
expect(result).toEqual({ pid: 222, killed: true, cleaned: true });
});
});

File diff suppressed because it is too large Load Diff

View File

@ -24,13 +24,18 @@ import {
getSessionsDir,
getWorktreesDir,
getArchiveDir,
getLogsDir,
getRetrospectivesDir,
getOriginFilePath,
generateSessionName,
generateTmuxName,
parseTmuxName,
expandHome,
validateAndStoreOrigin,
resolveProjectLogDir,
resolveProjectRetroDir,
} from "../paths.js";
import type { OrchestratorConfig, ProjectConfig } from "../types.js";
describe("Hash Generation", () => {
let tmpDir: string;
@ -479,6 +484,185 @@ describe("Origin File Management", () => {
});
});
describe("Logs and Retrospectives Directories", () => {
let tmpDir: string;
let configPath: string;
beforeEach(() => {
tmpDir = mkdtempSync(join(tmpdir(), "logs-retro-test-"));
configPath = join(tmpDir, "agent-orchestrator.yaml");
writeFileSync(configPath, "projects: {}");
});
afterEach(() => {
rmSync(tmpDir, { recursive: true, force: true });
});
it("getLogsDir returns {baseDir}/logs", () => {
const logsDir = getLogsDir(configPath, "/repos/integrator");
expect(logsDir).toMatch(
/\.agent-orchestrator\/[a-f0-9]{12}-integrator\/logs$/,
);
});
it("getRetrospectivesDir returns {baseDir}/retrospectives", () => {
const retroDir = getRetrospectivesDir(configPath, "/repos/integrator");
expect(retroDir).toMatch(
/\.agent-orchestrator\/[a-f0-9]{12}-integrator\/retrospectives$/,
);
});
it("logs and retrospectives share the same base directory", () => {
const baseDir = getProjectBaseDir(configPath, "/repos/integrator");
const logsDir = getLogsDir(configPath, "/repos/integrator");
const retroDir = getRetrospectivesDir(configPath, "/repos/integrator");
expect(logsDir).toBe(join(baseDir, "logs"));
expect(retroDir).toBe(join(baseDir, "retrospectives"));
});
});
describe("resolveProjectLogDir", () => {
let tmpDir: string;
let configPath: string;
beforeEach(() => {
tmpDir = mkdtempSync(join(tmpdir(), "resolve-log-test-"));
configPath = join(tmpDir, "agent-orchestrator.yaml");
writeFileSync(configPath, "projects: {}");
});
afterEach(() => {
rmSync(tmpDir, { recursive: true, force: true });
});
it("returns null when no projects are configured", () => {
const config = {
configPath,
readyThresholdMs: 300000,
defaults: { runtime: "tmux", agent: "claude-code", workspace: "worktree", notifiers: [] },
projects: {},
notifiers: {},
notificationRouting: {} as OrchestratorConfig["notificationRouting"],
reactions: {},
} satisfies OrchestratorConfig;
expect(resolveProjectLogDir(config)).toBeNull();
});
it("returns logs dir for the first project", () => {
const project: ProjectConfig = {
name: "Test",
repo: "owner/repo",
path: "/repos/integrator",
defaultBranch: "main",
sessionPrefix: "int",
};
const config = {
configPath,
readyThresholdMs: 300000,
defaults: { runtime: "tmux", agent: "claude-code", workspace: "worktree", notifiers: [] },
projects: { integrator: project },
notifiers: {},
notificationRouting: {} as OrchestratorConfig["notificationRouting"],
reactions: {},
} satisfies OrchestratorConfig;
const result = resolveProjectLogDir(config);
expect(result).not.toBeNull();
expect(result).toMatch(/\.agent-orchestrator\/[a-f0-9]{12}-integrator\/logs$/);
});
it("uses the first project when multiple are configured", () => {
const projectA: ProjectConfig = {
name: "Alpha",
repo: "owner/alpha",
path: "/repos/alpha",
defaultBranch: "main",
sessionPrefix: "alp",
};
const projectB: ProjectConfig = {
name: "Beta",
repo: "owner/beta",
path: "/repos/beta",
defaultBranch: "main",
sessionPrefix: "bet",
};
const config = {
configPath,
readyThresholdMs: 300000,
defaults: { runtime: "tmux", agent: "claude-code", workspace: "worktree", notifiers: [] },
projects: { alpha: projectA, beta: projectB },
notifiers: {},
notificationRouting: {} as OrchestratorConfig["notificationRouting"],
reactions: {},
} satisfies OrchestratorConfig;
const result = resolveProjectLogDir(config);
// Should resolve to the first project (alpha)
expect(result).toMatch(/alpha\/logs$/);
});
});
describe("resolveProjectRetroDir", () => {
let tmpDir: string;
let configPath: string;
beforeEach(() => {
tmpDir = mkdtempSync(join(tmpdir(), "resolve-retro-test-"));
configPath = join(tmpDir, "agent-orchestrator.yaml");
writeFileSync(configPath, "projects: {}");
});
afterEach(() => {
rmSync(tmpDir, { recursive: true, force: true });
});
it("returns null when no projects are configured", () => {
const config = {
configPath,
readyThresholdMs: 300000,
defaults: { runtime: "tmux", agent: "claude-code", workspace: "worktree", notifiers: [] },
projects: {},
notifiers: {},
notificationRouting: {} as OrchestratorConfig["notificationRouting"],
reactions: {},
} satisfies OrchestratorConfig;
expect(resolveProjectRetroDir(config)).toBeNull();
});
it("returns retrospectives dir for the first project", () => {
const project: ProjectConfig = {
name: "Test",
repo: "owner/repo",
path: "/repos/integrator",
defaultBranch: "main",
sessionPrefix: "int",
};
const config = {
configPath,
readyThresholdMs: 300000,
defaults: { runtime: "tmux", agent: "claude-code", workspace: "worktree", notifiers: [] },
projects: { integrator: project },
notifiers: {},
notificationRouting: {} as OrchestratorConfig["notificationRouting"],
reactions: {},
} satisfies OrchestratorConfig;
const result = resolveProjectRetroDir(config);
expect(result).not.toBeNull();
expect(result).toMatch(
/\.agent-orchestrator\/[a-f0-9]{12}-integrator\/retrospectives$/,
);
});
});
describe("Hash Collision Probability", () => {
it("documents expected collision rate", () => {
// 12 hex chars = 48 bits of entropy

View File

@ -1,10 +1,45 @@
import { describe, it, expect, beforeEach, afterEach } from "vitest";
import { describe, it, expect, beforeEach, afterEach, vi } from "vitest";
import { mkdirSync, rmSync, writeFileSync, readFileSync, readdirSync } from "node:fs";
import { join } from "node:path";
import { tmpdir } from "node:os";
import { randomUUID } from "node:crypto";
import type { Retrospective } from "../types.js";
import { saveRetrospective, loadRetrospectives } from "../retrospective.js";
import type { Retrospective, SessionReportCard, LogEntry } from "../types.js";
// ---------------------------------------------------------------------------
// Mocks for generateRetrospective dependencies (hoisted before imports)
// ---------------------------------------------------------------------------
const { mockReadMetadataRaw, mockGenerateReportCard, mockReadLogs, mockGetSessionsDir, mockGetLogsDir } =
vi.hoisted(() => ({
mockReadMetadataRaw: vi.fn(),
mockGenerateReportCard: vi.fn(),
mockReadLogs: vi.fn(),
mockGetSessionsDir: vi.fn(),
mockGetLogsDir: vi.fn(),
}));
vi.mock("../metadata.js", () => ({
readMetadataRaw: mockReadMetadataRaw,
}));
vi.mock("../session-report-card.js", () => ({
generateReportCard: mockGenerateReportCard,
}));
vi.mock("../log-reader.js", () => ({
readLogs: mockReadLogs,
}));
vi.mock("../paths.js", () => ({
getSessionsDir: mockGetSessionsDir,
getLogsDir: mockGetLogsDir,
}));
// ---------------------------------------------------------------------------
// Imports — after mocks so they resolve the mocked modules
// ---------------------------------------------------------------------------
import { saveRetrospective, loadRetrospectives, generateRetrospective } from "../retrospective.js";
let tmpDir: string;
let retroDir: string;
@ -309,3 +344,711 @@ describe("loadRetrospectives", () => {
expect(loaded.timeline).toHaveLength(2);
});
});
// ===========================================================================
// generateRetrospective + extractLessons (via mocked dependencies)
// ===========================================================================
/** Helper to build a SessionReportCard with sensible defaults. */
function makeReportCard(overrides: Partial<SessionReportCard> = {}): SessionReportCard {
return {
sessionId: "test-1",
projectId: "my-project",
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T12:00:00.000Z",
totalMs: 7_200_000, // 2 hours
},
stateTransitions: [],
ciAttempts: 0,
reviewRounds: 0,
outcome: "merged",
prUrl: "https://github.com/org/repo/pull/42",
...overrides,
};
}
/** Helper to build a LogEntry with sensible defaults. */
function makeLogEntry(overrides: Partial<LogEntry> = {}): LogEntry {
return {
ts: "2025-06-01T10:00:00.000Z",
level: "info",
source: "lifecycle",
sessionId: "test-1",
message: "event",
...overrides,
};
}
/** Config fixture for generateRetrospective. */
function makeConfig(): {
config: { configPath: string; projects: Record<string, { path: string }> };
} {
return {
config: {
configPath: "/tmp/agent-orchestrator.yaml",
projects: {
"my-project": { path: "/tmp/repos/my-project" },
},
},
};
}
/**
* Set up standard mocks for generateRetrospective.
* Returns the default report card so tests can override fields.
*/
function setupGenerateMocks(opts?: {
metadata?: Record<string, string> | null;
archiveMetadata?: Record<string, string> | null;
reportCard?: Partial<SessionReportCard>;
logEntries?: LogEntry[];
}): SessionReportCard {
mockGetSessionsDir.mockReturnValue("/tmp/sessions");
mockGetLogsDir.mockReturnValue("/tmp/logs");
// First call: live metadata. Second call: archive metadata.
if (opts?.metadata !== undefined) {
mockReadMetadataRaw.mockReturnValueOnce(opts.metadata);
} else {
mockReadMetadataRaw.mockReturnValueOnce({ project: "my-project" });
}
if (opts?.archiveMetadata !== undefined) {
mockReadMetadataRaw.mockReturnValueOnce(opts.archiveMetadata);
}
const card = makeReportCard(opts?.reportCard);
mockGenerateReportCard.mockReturnValue(card);
const entries = opts?.logEntries ?? [];
mockReadLogs.mockReturnValue(entries);
return card;
}
describe("generateRetrospective", () => {
beforeEach(() => {
vi.clearAllMocks();
});
it("returns null for unknown project", () => {
const { config } = makeConfig();
const result = generateRetrospective("test-1", config as never, "nonexistent");
expect(result).toBeNull();
});
it("generates a retrospective for a successful session (merged PR)", () => {
const { config } = makeConfig();
const entries = [
makeLogEntry({ ts: "2025-06-01T10:00:00.000Z", message: "session spawned", data: { type: "spawned" } }),
makeLogEntry({ ts: "2025-06-01T10:30:00.000Z", message: "PR opened", data: { type: "pr.opened" } }),
makeLogEntry({ ts: "2025-06-01T11:00:00.000Z", message: "PR merged", data: { type: "pr.merged" } }),
];
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 0,
prUrl: "https://github.com/org/repo/pull/42",
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T11:00:00.000Z",
totalMs: 3_600_000, // 1 hour
},
},
logEntries: entries,
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
expect(result!.sessionId).toBe("test-1");
expect(result!.projectId).toBe("my-project");
expect(result!.outcome).toBe("success");
expect(result!.timeline).toHaveLength(3);
expect(result!.metrics.totalDurationMs).toBe(3_600_000);
expect(result!.metrics.ciFailures).toBe(0);
expect(result!.metrics.reviewRounds).toBe(0);
expect(result!.reportCard.outcome).toBe("merged");
expect(result!.lessons).toContain(
"Clean execution: merged quickly with minimal CI/review iterations.",
);
});
it("generates a retrospective for a failed session (killed, no PR)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "killed",
prUrl: null,
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T11:00:00.000Z",
totalMs: 3_600_000,
},
},
logEntries: [
makeLogEntry({ ts: "2025-06-01T10:00:00.000Z", message: "session spawned" }),
makeLogEntry({ ts: "2025-06-01T11:00:00.000Z", message: "session killed" }),
],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
expect(result!.outcome).toBe("failure");
expect(result!.lessons).toContain(
"Session was killed without creating a PR. May indicate a stuck or misdirected session.",
);
});
it("generates a retrospective for partial success (PR open but killed)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "active",
prUrl: "https://github.com/org/repo/pull/99",
ciAttempts: 1,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T14:00:00.000Z",
totalMs: 14_400_000, // 4 hours
},
},
logEntries: [
makeLogEntry({ ts: "2025-06-01T10:00:00.000Z", message: "session spawned" }),
],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
expect(result!.outcome).toBe("partial");
});
it("maps abandoned outcome to failure", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "abandoned",
prUrl: null,
ciAttempts: 0,
reviewRounds: 0,
},
logEntries: [],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
expect(result!.outcome).toBe("failure");
});
it("extracts timeline events from log entries", () => {
const { config } = makeConfig();
const entries = [
makeLogEntry({
ts: "2025-06-01T10:00:00.000Z",
message: "session spawned",
data: { type: "spawned" },
}),
makeLogEntry({
ts: "2025-06-01T10:30:00.000Z",
message: "CI passed",
data: { type: "ci.passing" },
}),
makeLogEntry({
ts: "2025-06-01T11:00:00.000Z",
level: "warn",
message: "warning event",
}),
];
setupGenerateMocks({
reportCard: { outcome: "merged" },
logEntries: entries,
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.timeline).toHaveLength(3);
expect(result!.timeline[0]).toEqual({
event: "spawned",
at: "2025-06-01T10:00:00.000Z",
detail: "session spawned",
});
expect(result!.timeline[1]).toEqual({
event: "ci.passing",
at: "2025-06-01T10:30:00.000Z",
detail: "CI passed",
});
// When data.type is absent, falls back to entry.level
expect(result!.timeline[2]).toEqual({
event: "warn",
at: "2025-06-01T11:00:00.000Z",
detail: "warning event",
});
});
it("falls back to level when data.type is missing in timeline", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: { outcome: "merged" },
logEntries: [
makeLogEntry({ level: "error", message: "something broke" }),
],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.timeline[0].event).toBe("error");
});
it("falls back to archive dir when live metadata is missing", () => {
const { config } = makeConfig();
setupGenerateMocks({
metadata: null,
archiveMetadata: { project: "my-project", branch: "feat/old" },
reportCard: { outcome: "merged" },
logEntries: [],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
// readMetadataRaw called twice: once for live, once for archive
expect(mockReadMetadataRaw).toHaveBeenCalledTimes(2);
expect(mockReadMetadataRaw).toHaveBeenNthCalledWith(1, "/tmp/sessions", "test-1");
expect(mockReadMetadataRaw).toHaveBeenNthCalledWith(
2,
join("/tmp/sessions", "archive"),
"test-1",
);
});
it("uses fallback metadata when no files found (live or archive)", () => {
const { config } = makeConfig();
setupGenerateMocks({
metadata: null,
archiveMetadata: null,
reportCard: { outcome: "active" },
logEntries: [],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result).not.toBeNull();
// generateReportCard receives { project: projectId } as fallback
expect(mockGenerateReportCard).toHaveBeenCalledWith(
"test-1",
join("/tmp/logs", "events.jsonl"),
{ project: "my-project" },
);
});
it("passes the correct eventsLogPath to generateReportCard and readLogs", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: { outcome: "merged" },
logEntries: [],
});
generateRetrospective("test-1", config as never, "my-project");
const expectedPath = join("/tmp/logs", "events.jsonl");
expect(mockGenerateReportCard).toHaveBeenCalledWith("test-1", expectedPath, expect.any(Object));
expect(mockReadLogs).toHaveBeenCalledWith(expectedPath, { sessionId: "test-1" });
});
it("includes generatedAt timestamp", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: { outcome: "merged" },
logEntries: [],
});
const before = new Date().toISOString();
const result = generateRetrospective("test-1", config as never, "my-project");
const after = new Date().toISOString();
expect(result!.generatedAt).toBeDefined();
expect(result!.generatedAt >= before).toBe(true);
expect(result!.generatedAt <= after).toBe(true);
});
});
// ===========================================================================
// extractLessons — exercised through generateRetrospective
// ===========================================================================
describe("extractLessons (via generateRetrospective)", () => {
beforeEach(() => {
vi.clearAllMocks();
});
it("flags high CI failure count (>3 failures)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 5,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T14:00:00.000Z", totalMs: 14_400_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"High CI failure count (5 failures). Consider running tests locally before pushing.",
);
});
it("flags moderate CI failures (>1 but <=3)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 2,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T14:00:00.000Z", totalMs: 14_400_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain("CI failed 2 times before passing.");
// Should NOT contain the "High CI failure count" message
expect(result!.lessons.some((l) => l.includes("High CI failure count"))).toBe(false);
});
it("flags exactly 3 CI failures with moderate message (not high)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 3,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T14:00:00.000Z", totalMs: 14_400_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain("CI failed 3 times before passing.");
expect(result!.lessons.some((l) => l.includes("High CI failure count"))).toBe(false);
});
it("flags multiple review rounds (>2)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 3,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T14:00:00.000Z", totalMs: 14_400_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"Multiple review rounds (3). Breaking changes into smaller PRs may help.",
);
});
it("does not flag review rounds when <=2", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 2,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T14:00:00.000Z", totalMs: 14_400_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("Multiple review rounds"))).toBe(false);
});
it("flags long-running sessions (>24 hours)", () => {
const { config } = makeConfig();
const thirtyHoursMs = 30 * 3_600_000;
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T00:00:00.000Z",
endedAt: "2025-06-02T06:00:00.000Z",
totalMs: thirtyHoursMs,
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"Session ran for 30 hours. Long-running sessions may indicate complexity or blocking.",
);
});
it("does not flag sessions under 24 hours for duration", () => {
const { config } = makeConfig();
const twentyHoursMs = 20 * 3_600_000;
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T00:00:00.000Z",
endedAt: "2025-06-01T20:00:00.000Z",
totalMs: twentyHoursMs,
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("Long-running sessions"))).toBe(false);
});
it("flags quick success (<1 hour, merged, no CI or review issues)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T10:30:00.000Z",
totalMs: 1_800_000, // 30 minutes
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"Clean execution: merged quickly with minimal CI/review iterations.",
);
});
it("does not flag quick success when CI failed once", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 2,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T10:30:00.000Z",
totalMs: 1_800_000,
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("Clean execution"))).toBe(false);
});
it("does not flag quick success when not merged", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "active",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T10:30:00.000Z",
totalMs: 1_800_000,
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("Clean execution"))).toBe(false);
});
it("flags quick success under 2 hours threshold", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 1,
reviewRounds: 1,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T11:30:00.000Z",
totalMs: 5_400_000, // 1.5 hours
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"Clean execution: merged quickly with minimal CI/review iterations.",
);
});
it("does not flag quick success at exactly 2 hours", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T12:00:00.000Z",
totalMs: 7_200_000, // exactly 2 hours
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("Clean execution"))).toBe(false);
});
it("flags killed without PR", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "killed",
prUrl: null,
ciAttempts: 0,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T11:00:00.000Z", totalMs: 3_600_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"Session was killed without creating a PR. May indicate a stuck or misdirected session.",
);
});
it("does not flag killed with PR", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "killed",
prUrl: "https://github.com/org/repo/pull/42",
ciAttempts: 0,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: "2025-06-01T11:00:00.000Z", totalMs: 3_600_000 },
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons.some((l) => l.includes("killed without creating a PR"))).toBe(false);
});
it("flags no events recorded (empty timeline)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "active",
ciAttempts: 0,
reviewRounds: 0,
duration: { startedAt: "2025-06-01T10:00:00.000Z", endedAt: null, totalMs: 1_000 },
},
logEntries: [],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toContain(
"No lifecycle events recorded. Session may have been very short-lived or logging was not active.",
);
});
it("returns multiple lessons when multiple patterns match", () => {
const { config } = makeConfig();
const fiftyHoursMs = 50 * 3_600_000;
setupGenerateMocks({
reportCard: {
outcome: "killed",
prUrl: null,
ciAttempts: 5,
reviewRounds: 4,
duration: {
startedAt: "2025-06-01T00:00:00.000Z",
endedAt: "2025-06-03T02:00:00.000Z",
totalMs: fiftyHoursMs,
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
// Should have: high CI failure, multiple review rounds, long duration, killed without PR
expect(result!.lessons).toContain(
"High CI failure count (5 failures). Consider running tests locally before pushing.",
);
expect(result!.lessons).toContain(
"Multiple review rounds (4). Breaking changes into smaller PRs may help.",
);
expect(result!.lessons).toContain(
"Session ran for 50 hours. Long-running sessions may indicate complexity or blocking.",
);
expect(result!.lessons).toContain(
"Session was killed without creating a PR. May indicate a stuck or misdirected session.",
);
expect(result!.lessons).toHaveLength(4);
});
it("returns empty lessons for a clean session (no issues)", () => {
const { config } = makeConfig();
setupGenerateMocks({
reportCard: {
outcome: "merged",
prUrl: "https://github.com/org/repo/pull/42",
ciAttempts: 0,
reviewRounds: 0,
duration: {
startedAt: "2025-06-01T10:00:00.000Z",
endedAt: "2025-06-01T14:00:00.000Z",
totalMs: 14_400_000, // 4 hours (between 2h and 24h, so no quick success or duration flag)
},
},
logEntries: [makeLogEntry()],
});
const result = generateRetrospective("test-1", config as never, "my-project");
expect(result!.lessons).toEqual([]);
});
});

View File

@ -1,5 +1,5 @@
import { describe, it, expect } from "vitest";
import { percentile, normalizeRoutePath } from "../utils.js";
import { percentile, normalizeRoutePath, shellEscape, escapeAppleScript, validateUrl } from "../utils.js";
describe("percentile", () => {
it("returns 0 for empty array", () => {
@ -77,3 +77,125 @@ describe("normalizeRoutePath", () => {
);
});
});
describe("shellEscape", () => {
it("wraps a simple string in single quotes", () => {
expect(shellEscape("hello")).toBe("'hello'");
});
it("handles empty string", () => {
expect(shellEscape("")).toBe("''");
});
it("escapes embedded single quotes", () => {
expect(shellEscape("it's")).toBe("'it'\\''s'");
});
it("escapes multiple single quotes", () => {
expect(shellEscape("it's a 'test'")).toBe("'it'\\''s a '\\''test'\\'''");
});
it("preserves dollar signs without expansion", () => {
// Single-quoted strings in POSIX shells do not expand $
expect(shellEscape("$HOME")).toBe("'$HOME'");
});
it("preserves backticks without expansion", () => {
expect(shellEscape("`whoami`")).toBe("'`whoami`'");
});
it("preserves double quotes literally", () => {
expect(shellEscape('say "hello"')).toBe("'say \"hello\"'");
});
it("preserves spaces and special characters", () => {
expect(shellEscape("hello world!")).toBe("'hello world!'");
expect(shellEscape("a&b|c;d")).toBe("'a&b|c;d'");
});
it("preserves newlines", () => {
expect(shellEscape("line1\nline2")).toBe("'line1\nline2'");
});
});
describe("escapeAppleScript", () => {
it("returns simple string unchanged", () => {
expect(escapeAppleScript("hello")).toBe("hello");
});
it("escapes double quotes", () => {
expect(escapeAppleScript('say "hello"')).toBe('say \\"hello\\"');
});
it("escapes backslashes", () => {
expect(escapeAppleScript("path\\to\\file")).toBe("path\\\\to\\\\file");
});
it("escapes both backslashes and double quotes", () => {
expect(escapeAppleScript('a\\b"c')).toBe('a\\\\b\\"c');
});
it("handles empty string", () => {
expect(escapeAppleScript("")).toBe("");
});
it("handles string with only backslashes", () => {
expect(escapeAppleScript("\\\\")).toBe("\\\\\\\\");
});
it("handles string with only double quotes", () => {
expect(escapeAppleScript('""')).toBe('\\"\\"');
});
it("preserves single quotes (not special in AppleScript double-quoted strings)", () => {
expect(escapeAppleScript("it's fine")).toBe("it's fine");
});
});
describe("validateUrl", () => {
it("accepts valid https URL", () => {
expect(() => validateUrl("https://example.com", "test")).not.toThrow();
});
it("accepts valid http URL", () => {
expect(() => validateUrl("http://example.com", "test")).not.toThrow();
});
it("accepts https URL with path and query", () => {
expect(() =>
validateUrl("https://api.github.com/repos/owner/repo?page=1", "github"),
).not.toThrow();
});
it("rejects ftp URL", () => {
expect(() => validateUrl("ftp://files.example.com", "test")).toThrow(
/Invalid url: must be http\(s\)/,
);
});
it("rejects URL without protocol", () => {
expect(() => validateUrl("example.com", "test")).toThrow(
/Invalid url: must be http\(s\)/,
);
});
it("rejects empty string", () => {
expect(() => validateUrl("", "test")).toThrow(
/Invalid url: must be http\(s\)/,
);
});
it("rejects mailto URL", () => {
expect(() => validateUrl("mailto:user@example.com", "test")).toThrow(
/Invalid url: must be http\(s\)/,
);
});
it("includes label in error message", () => {
expect(() => validateUrl("bad-url", "my-plugin")).toThrow("[my-plugin]");
});
it("includes the invalid URL in error message", () => {
expect(() => validateUrl("ftp://bad", "test")).toThrow("ftp://bad");
});
});

View File

@ -159,8 +159,8 @@ export async function restartDashboard(opts: DashboardRestartOpts): Promise<Dash
if (opts.configPath) {
env["AO_CONFIG_PATH"] = opts.configPath;
}
env["NEXT_PUBLIC_TERMINAL_PORT"] = env["TERMINAL_PORT"] ?? "3001";
env["NEXT_PUBLIC_DIRECT_TERMINAL_PORT"] = env["DIRECT_TERMINAL_PORT"] ?? "3003";
env["NEXT_PUBLIC_TERMINAL_PORT"] = env["TERMINAL_PORT"] ?? "14800";
env["NEXT_PUBLIC_DIRECT_TERMINAL_PORT"] = env["DIRECT_TERMINAL_PORT"] ?? "14801";
const child = spawn("npx", ["next", "dev", "-p", String(port)], {
cwd: opts.webDir,

View File

@ -89,7 +89,8 @@ export { LogWriter } from "./log-writer.js";
export type { LogWriterOptions } from "./log-writer.js";
// Log reader — query and filter JSONL logs
export { readLogs, readLogsFromDir, tailLogs } from "./log-reader.js";
export { readLogs, readLogsFromDir, tailLogs, parseApiLogs } from "./log-reader.js";
export type { ApiLogEntry } from "./log-reader.js";
// Session report card — per-session metrics
export { generateReportCard } from "./session-report-card.js";

View File

@ -161,3 +161,56 @@ function extractBackupNumber(filename: string): number {
function escapeRegex(str: string): string {
return str.replace(/[.*+?^${}()|[\]\\]/g, "\\$&");
}
/**
* A parsed API request log entry common type shared between the CLI and dashboard.
* Includes sessionId from the underlying LogEntry (null if not session-scoped).
*/
export interface ApiLogEntry {
ts: string;
method: string;
path: string;
sessionId: string | null;
statusCode: number;
durationMs: number;
error?: string;
timings?: Record<string, number>;
cacheStats?: { hits: number; misses: number; hitRate: number; size: number };
}
/**
* Parse API log entries from a log directory into typed request objects.
* Shared by both `ao perf` CLI and the web dashboard's `/api/perf` route.
*/
export function parseApiLogs(
logDir: string,
opts?: { since?: Date; route?: string },
): ApiLogEntry[] {
const entries = readLogsFromDir(logDir, "api", {
source: "api",
since: opts?.since,
});
const results: ApiLogEntry[] = [];
for (const entry of entries) {
const data = entry.data ?? {};
if (!data["method"] || !data["path"]) continue;
const req: ApiLogEntry = {
ts: entry.ts,
method: String(data["method"]),
path: String(data["path"]),
sessionId: entry.sessionId,
statusCode: Number(data["statusCode"]) || 0,
durationMs: Number(data["durationMs"]) || 0,
error: data["error"] ? String(data["error"]) : undefined,
timings: data["timings"] as Record<string, number> | undefined,
cacheStats: data["cacheStats"] as ApiLogEntry["cacheStats"] | undefined,
};
if (opts?.route && !req.path.includes(opts.route)) continue;
results.push(req);
}
return results;
}

View File

@ -138,6 +138,110 @@ describe("GET /api/logs", () => {
const json = await res.json();
expect(json.error).toMatch(/No projects configured/);
});
it("passes since parameter as a Date object to query options", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?since=2026-01-15T10:00:00Z",
);
await logsGET(req);
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"events",
expect.objectContaining({
since: new Date("2026-01-15T10:00:00Z"),
limit: 200,
}),
);
});
it("parses comma-separated level parameter into an array", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?level=info,warn,error",
);
await logsGET(req);
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"events",
expect.objectContaining({
level: ["info", "warn", "error"],
}),
);
});
it("passes sessionId parameter to query options", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?sessionId=backend-3",
);
await logsGET(req);
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"events",
expect.objectContaining({
sessionId: "backend-3",
}),
);
});
it("applies combined filters (source + level + since)", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?source=dashboard&level=error,warn&since=2026-02-01T00:00:00Z&limit=50",
);
await logsGET(req);
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"dashboard",
{
since: new Date("2026-02-01T00:00:00Z"),
level: ["error", "warn"],
limit: 50,
},
);
});
it("handles non-numeric limit parameter gracefully (defaults to NaN)", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?limit=notanumber",
);
await logsGET(req);
// parseInt("notanumber", 10) returns NaN — still passed to readLogsFromDir
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"events",
expect.objectContaining({ limit: NaN }),
);
});
it("handles non-numeric tail parameter gracefully", async () => {
mockTailLogs.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/logs?tail=abc",
);
const res = await logsGET(req);
expect(res.status).toBe(200);
// parseInt("abc", 10) returns NaN — still calls tailLogs with NaN
expect(mockTailLogs).toHaveBeenCalledWith(
"/tmp/test-logs/events.jsonl",
NaN,
);
expect(mockReadLogsFromDir).not.toHaveBeenCalled();
});
});
// ── GET /api/perf ───────────────────────────────────────────────────────
@ -281,6 +385,222 @@ describe("GET /api/perf", () => {
const json = await res.json();
expect(json.error).toMatch(/No projects configured/);
});
it("passes since parameter as Date to readLogsFromDir", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request(
"http://localhost:3000/api/perf?since=2026-02-01T12:00:00Z",
);
await perfGET(req);
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"api",
expect.objectContaining({
source: "api",
since: new Date("2026-02-01T12:00:00Z"),
}),
);
});
it("filters entries by route parameter using path.includes", async () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-01-01T00:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "GET", path: "/api/sessions", statusCode: 200, durationMs: 100 },
},
{
ts: "2026-01-01T00:01:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "POST", path: "/api/spawn", statusCode: 200, durationMs: 200 },
},
{
ts: "2026-01-01T00:02:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "GET", path: "/api/sessions/s-1", statusCode: 200, durationMs: 150 },
},
]);
const req = new Request("http://localhost:3000/api/perf?route=sessions");
const res = await perfGET(req);
const json = await res.json();
// Only entries whose path includes "sessions" should appear
expect(json.totalRequests).toBe(3); // totalRequests is entries.length (all from readLogsFromDir)
// But routes should only contain session-related entries
expect(json.routes["POST /api/spawn"]).toBeUndefined();
expect(json.routes["GET /api/sessions"]).toBeDefined();
expect(json.routes["GET /api/sessions/:id"]).toBeDefined();
});
it("returns zeroed stats when no log entries exist", async () => {
mockReadLogsFromDir.mockReturnValue([]);
const req = new Request("http://localhost:3000/api/perf");
const res = await perfGET(req);
expect(res.status).toBe(200);
const json = await res.json();
expect(json.routes).toEqual({});
expect(json.slowest).toEqual([]);
expect(json.cacheStats).toBeNull();
expect(json.totalRequests).toBe(0);
});
it("returns latestCacheStats from the most recent entry with cacheStats", async () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-01-01T00:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: {
method: "GET",
path: "/api/sessions",
statusCode: 200,
durationMs: 100,
cacheStats: { hits: 5, misses: 2 },
},
},
{
ts: "2026-01-01T00:01:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: {
method: "GET",
path: "/api/sessions",
statusCode: 200,
durationMs: 120,
cacheStats: { hits: 10, misses: 3 },
},
},
{
ts: "2026-01-01T00:02:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: {
method: "GET",
path: "/api/sessions",
statusCode: 200,
durationMs: 80,
// no cacheStats in this entry
},
},
]);
const req = new Request("http://localhost:3000/api/perf");
const res = await perfGET(req);
const json = await res.json();
// Should be the last entry that had cacheStats (the second one)
expect(json.cacheStats).toEqual({ hits: 10, misses: 3 });
});
it("skips entries with missing method or path fields", async () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-01-01T00:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { path: "/api/sessions", statusCode: 200, durationMs: 100 },
// missing method
},
{
ts: "2026-01-01T00:01:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "GET", statusCode: 200, durationMs: 200 },
// missing path
},
{
ts: "2026-01-01T00:02:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: {},
// missing both
},
{
ts: "2026-01-01T00:03:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
// no data field at all (data will be undefined, ?? {} makes it {})
},
]);
const req = new Request("http://localhost:3000/api/perf");
const res = await perfGET(req);
const json = await res.json();
// All entries should be skipped — no routes recorded
expect(json.routes).toEqual({});
expect(json.slowest).toEqual([]);
expect(json.totalRequests).toBe(4); // entries.length from readLogsFromDir
});
it("applies combined since + route filtering", async () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-02-01T10:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "GET", path: "/api/sessions", statusCode: 200, durationMs: 100 },
},
{
ts: "2026-02-01T11:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "req",
data: { method: "POST", path: "/api/spawn", statusCode: 200, durationMs: 300 },
},
]);
const req = new Request(
"http://localhost:3000/api/perf?since=2026-02-01T00:00:00Z&route=spawn",
);
const res = await perfGET(req);
const json = await res.json();
// since is passed to readLogsFromDir
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/test-logs",
"api",
expect.objectContaining({
since: new Date("2026-02-01T00:00:00Z"),
}),
);
// route filtering happens in-memory — only spawn should appear in routes
expect(json.routes["POST /api/spawn"]).toBeDefined();
expect(json.routes["POST /api/spawn"].count).toBe(1);
expect(json.routes["GET /api/sessions"]).toBeUndefined();
});
});
// ── POST /api/client-logs ───────────────────────────────────────────────
@ -420,4 +740,131 @@ describe("POST /api/client-logs", () => {
expect(json.ok).toBe(true);
expect(json.logged).toBe(0);
});
it("includes optional fields (url, stack, timing) in data when present", async () => {
const req = new Request("http://localhost:3000/api/client-logs", {
method: "POST",
body: JSON.stringify({
entries: [
{
level: "error",
message: "API call failed",
url: "/api/sessions",
stack: "TypeError: fetch failed\n at fetchSessions (app.js:42)",
timing: { fetchMs: 2500, renderMs: 12 },
},
],
}),
headers: { "Content-Type": "application/json" },
});
const res = await clientLogsPost(req);
expect(res.status).toBe(200);
const json = await res.json();
expect(json.logged).toBe(1);
const call = mockLogWriterAppend.mock.calls[0][0];
expect(call.level).toBe("error");
expect(call.message).toBe("API call failed");
expect(call.data).toEqual({
url: "/api/sessions",
stack: "TypeError: fetch failed\n at fetchSessions (app.js:42)",
timing: { fetchMs: 2500, renderMs: 12 },
});
});
it("omits optional fields from data when they are falsy", async () => {
const req = new Request("http://localhost:3000/api/client-logs", {
method: "POST",
body: JSON.stringify({
entries: [
{
level: "info",
message: "page loaded",
url: undefined,
stack: null,
timing: undefined,
},
],
}),
headers: { "Content-Type": "application/json" },
});
const res = await clientLogsPost(req);
expect(res.status).toBe(200);
const json = await res.json();
expect(json.logged).toBe(1);
// Falsy optional fields should not appear in data
const call = mockLogWriterAppend.mock.calls[0][0];
expect(call.data).toEqual({});
expect(call.data).not.toHaveProperty("url");
expect(call.data).not.toHaveProperty("stack");
expect(call.data).not.toHaveProperty("timing");
});
it("logs multiple valid entries in a batch and returns correct count", async () => {
const req = new Request("http://localhost:3000/api/client-logs", {
method: "POST",
body: JSON.stringify({
entries: [
{ level: "info", message: "page loaded" },
{ level: "warn", message: "slow render" },
{ level: "error", message: "crash detected" },
{ level: "info", message: "navigation complete" },
{ level: "warn", message: "memory high" },
],
}),
headers: { "Content-Type": "application/json" },
});
const res = await clientLogsPost(req);
expect(res.status).toBe(200);
const json = await res.json();
expect(json.ok).toBe(true);
expect(json.logged).toBe(5);
expect(mockLogWriterAppend).toHaveBeenCalledTimes(5);
// Verify each call has source: "browser" and sessionId: null
for (let i = 0; i < 5; i++) {
const call = mockLogWriterAppend.mock.calls[i][0];
expect(call.source).toBe("browser");
expect(call.sessionId).toBeNull();
expect(call.ts).toBeDefined();
}
});
it("accepts a mix of valid and invalid entries (partial acceptance)", async () => {
const req = new Request("http://localhost:3000/api/client-logs", {
method: "POST",
body: JSON.stringify({
entries: [
{ level: "info", message: "good entry 1" }, // valid
{ level: "debug", message: "bad level" }, // invalid: "debug" not in VALID_LEVELS
{ level: "error", message: "good entry 2" }, // valid
42, // invalid: not an object
null, // invalid: null
{ level: "warn" }, // invalid: no message
{ message: "no level" }, // invalid: no level
{ level: "warn", message: "good entry 3" }, // valid
],
}),
headers: { "Content-Type": "application/json" },
});
const res = await clientLogsPost(req);
expect(res.status).toBe(200);
const json = await res.json();
expect(json.ok).toBe(true);
expect(json.logged).toBe(3); // Only 3 valid entries
expect(mockLogWriterAppend).toHaveBeenCalledTimes(3);
expect(mockLogWriterAppend.mock.calls[0][0].message).toBe("good entry 1");
expect(mockLogWriterAppend.mock.calls[1][0].message).toBe("good entry 2");
expect(mockLogWriterAppend.mock.calls[2][0].message).toBe("good entry 3");
});
});

View File

@ -0,0 +1,977 @@
/**
* Tests for browser-side client logger.
*
* Covers:
* - window.onerror / unhandledrejection capture
* - PerformanceObserver integration (LCP, FCP, navigation)
* - Batch flush via fetch POST to /api/client-logs
* - sendBeacon usage on flush, with fetch fallback
* - Periodic flush timer
* - Visibility change flush
* - beforeunload (pagehide) flush
* - Cleanup function behavior
* - Graceful degradation when PerformanceObserver is unavailable
*
* The module under test uses module-level state (buffer, flushTimer).
* We use vi.resetModules() + dynamic import to get fresh state per test.
*/
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
// ---------------------------------------------------------------------------
// PromiseRejectionEvent polyfill for jsdom (not available by default)
// ---------------------------------------------------------------------------
if (typeof globalThis.PromiseRejectionEvent === "undefined") {
// Minimal polyfill that satisfies the code under test
class PromiseRejectionEventPolyfill extends Event {
readonly promise: Promise<unknown>;
readonly reason: unknown;
constructor(
type: string,
init: { promise: Promise<unknown>; reason?: unknown },
) {
super(type, { bubbles: false, cancelable: true });
this.promise = init.promise;
this.reason = init.reason;
}
}
// eslint-disable-next-line @typescript-eslint/no-explicit-any
(globalThis as any).PromiseRejectionEvent = PromiseRejectionEventPolyfill;
}
// ---------------------------------------------------------------------------
// Mock helpers
// ---------------------------------------------------------------------------
/** Captured PerformanceObserver callback from the most recent instantiation. */
let perfObserverCallback: ((list: { getEntries: () => unknown[] }) => void) | null = null;
let perfObserverObservedTypes: string[] = [];
let perfObserverDisconnected = false;
class MockPerformanceObserver {
callback: (list: { getEntries: () => unknown[] }) => void;
constructor(cb: (list: { getEntries: () => unknown[] }) => void) {
this.callback = cb;
perfObserverCallback = cb;
}
observe(opts: { type: string; buffered?: boolean }): void {
perfObserverObservedTypes.push(opts.type);
}
disconnect(): void {
perfObserverDisconnected = true;
}
}
// ---------------------------------------------------------------------------
// Setup and teardown
// ---------------------------------------------------------------------------
let fetchSpy: ReturnType<typeof vi.fn>;
let sendBeaconSpy: ReturnType<typeof vi.fn>;
let originalPerformanceObserver: typeof globalThis.PerformanceObserver | undefined;
/** Dynamically imported initClientLogger — fresh module state each test. */
let initClientLogger: () => () => void;
beforeEach(async () => {
vi.useFakeTimers();
// Reset PerformanceObserver tracking
perfObserverCallback = null;
perfObserverObservedTypes = [];
perfObserverDisconnected = false;
// Install mock PerformanceObserver
originalPerformanceObserver = globalThis.PerformanceObserver;
// eslint-disable-next-line @typescript-eslint/no-explicit-any
globalThis.PerformanceObserver = MockPerformanceObserver as any;
// Mock fetch
fetchSpy = vi.fn().mockResolvedValue({ ok: true });
globalThis.fetch = fetchSpy;
// Mock sendBeacon (returns true by default)
sendBeaconSpy = vi.fn().mockReturnValue(true);
Object.defineProperty(navigator, "sendBeacon", {
value: sendBeaconSpy,
writable: true,
configurable: true,
});
// Reset modules to get fresh module-level state (buffer, flushTimer)
vi.resetModules();
const mod = await import("../client-logger.js");
initClientLogger = mod.initClientLogger;
});
afterEach(() => {
vi.restoreAllMocks();
vi.useRealTimers();
// Restore PerformanceObserver
if (originalPerformanceObserver) {
globalThis.PerformanceObserver = originalPerformanceObserver;
}
});
// ---------------------------------------------------------------------------
// initClientLogger — basic setup
// ---------------------------------------------------------------------------
describe("initClientLogger", () => {
it("returns a cleanup function", () => {
const cleanup = initClientLogger();
expect(typeof cleanup).toBe("function");
cleanup();
});
it("registers error event listener on window", () => {
const addSpy = vi.spyOn(window, "addEventListener");
const cleanup = initClientLogger();
const errorCalls = addSpy.mock.calls.filter(([type]) => type === "error");
expect(errorCalls.length).toBe(1);
cleanup();
});
it("registers unhandledrejection event listener on window", () => {
const addSpy = vi.spyOn(window, "addEventListener");
const cleanup = initClientLogger();
const rejectionCalls = addSpy.mock.calls.filter(
([type]) => type === "unhandledrejection",
);
expect(rejectionCalls.length).toBe(1);
cleanup();
});
it("registers pagehide event listener on window", () => {
const addSpy = vi.spyOn(window, "addEventListener");
const cleanup = initClientLogger();
const pageCalls = addSpy.mock.calls.filter(([type]) => type === "pagehide");
expect(pageCalls.length).toBe(1);
cleanup();
});
it("registers visibilitychange event listener on window", () => {
const addSpy = vi.spyOn(window, "addEventListener");
const cleanup = initClientLogger();
const visCalls = addSpy.mock.calls.filter(
([type]) => type === "visibilitychange",
);
expect(visCalls.length).toBe(1);
cleanup();
});
it("sets up a periodic flush interval", () => {
const setIntervalSpy = vi.spyOn(globalThis, "setInterval");
const cleanup = initClientLogger();
// setInterval should have been called with 10_000 ms
const flushCalls = setIntervalSpy.mock.calls.filter(
([, ms]) => ms === 10_000,
);
expect(flushCalls.length).toBe(1);
cleanup();
});
});
// ---------------------------------------------------------------------------
// Error capture
// ---------------------------------------------------------------------------
describe("error capture", () => {
it("captures error events with message, filename, and stack", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
const errorEvent = new ErrorEvent("error", {
message: "Test error occurred",
filename: "https://example.com/app.js",
lineno: 42,
colno: 7,
error: new Error("Test error occurred"),
});
window.dispatchEvent(errorEvent);
// Advance timer to trigger flush
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].level).toBe("error");
expect(body.entries[0].message).toBe("Test error occurred");
expect(body.entries[0].url).toBe("https://example.com/app.js");
expect(body.entries[0].stack).toBeDefined();
cleanup();
});
it("captures error event with fallback message when message is empty", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
const errorEvent = new ErrorEvent("error", {
message: "",
filename: "app.js",
});
window.dispatchEvent(errorEvent);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("Unknown error");
expect(body.entries[0].level).toBe("error");
cleanup();
});
it("captures unhandled promise rejections with Error reason", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
const reason = new Error("Promise failed");
const event = new PromiseRejectionEvent("unhandledrejection", {
reason,
promise: Promise.resolve(),
});
window.dispatchEvent(event);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("Promise failed");
expect(body.entries[0].level).toBe("error");
expect(body.entries[0].stack).toBeDefined();
cleanup();
});
it("captures unhandled promise rejections with string reason", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
const event = new PromiseRejectionEvent("unhandledrejection", {
reason: "string rejection",
promise: Promise.resolve(),
});
window.dispatchEvent(event);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("string rejection");
expect(body.entries[0].stack).toBeUndefined();
cleanup();
});
it("captures unhandled promise rejections with non-Error non-string reason", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
const event = new PromiseRejectionEvent("unhandledrejection", {
reason: 42,
promise: Promise.resolve(),
});
window.dispatchEvent(event);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries[0].message).toBe("42");
expect(body.entries[0].stack).toBeUndefined();
cleanup();
});
});
// ---------------------------------------------------------------------------
// Flush mechanism
// ---------------------------------------------------------------------------
describe("flush mechanism", () => {
it("skips fetch when buffer is empty", () => {
const cleanup = initClientLogger();
// Advance timer -- no errors were recorded
vi.advanceTimersByTime(10_000);
expect(sendBeaconSpy).not.toHaveBeenCalled();
expect(fetchSpy).not.toHaveBeenCalled();
cleanup();
});
it("batches multiple entries into a single POST", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
// Dispatch two errors
window.dispatchEvent(
new ErrorEvent("error", { message: "Error 1", filename: "a.js" }),
);
window.dispatchEvent(
new ErrorEvent("error", { message: "Error 2", filename: "b.js" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(2);
expect(body.entries[0].message).toBe("Error 1");
expect(body.entries[1].message).toBe("Error 2");
cleanup();
});
it("uses sendBeacon for flush and skips fetch when sendBeacon succeeds", () => {
sendBeaconSpy.mockReturnValue(true);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "beacon test" }),
);
vi.advanceTimersByTime(10_000);
expect(sendBeaconSpy).toHaveBeenCalledTimes(1);
expect(sendBeaconSpy.mock.calls[0][0]).toBe("/api/client-logs");
expect(fetchSpy).not.toHaveBeenCalled();
cleanup();
});
it("falls back to fetch when sendBeacon returns false", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "fallback test" }),
);
vi.advanceTimersByTime(10_000);
expect(sendBeaconSpy).toHaveBeenCalledTimes(1);
expect(fetchSpy).toHaveBeenCalledTimes(1);
expect(fetchSpy.mock.calls[0][0]).toBe("/api/client-logs");
expect(fetchSpy.mock.calls[0][1].method).toBe("POST");
expect(fetchSpy.mock.calls[0][1].keepalive).toBe(true);
cleanup();
});
it("falls back to fetch when sendBeacon is not available", () => {
// Remove sendBeacon
Object.defineProperty(navigator, "sendBeacon", {
value: undefined,
writable: true,
configurable: true,
});
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "no beacon" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries[0].message).toBe("no beacon");
cleanup();
});
it("sends correct Content-Type header in fetch fallback", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "header check" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy.mock.calls[0][1].headers).toEqual({
"Content-Type": "application/json",
});
cleanup();
});
it("does not crash when fetch rejects", () => {
sendBeaconSpy.mockReturnValue(false);
fetchSpy.mockRejectedValue(new Error("network error"));
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "fetch will fail" }),
);
// Should not throw
expect(() => vi.advanceTimersByTime(10_000)).not.toThrow();
cleanup();
});
it("clears the buffer after flushing", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "first batch" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
// Second interval: nothing new was added, so flush should be skipped
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1); // Still 1
cleanup();
});
});
// ---------------------------------------------------------------------------
// Visibility change and pagehide
// ---------------------------------------------------------------------------
describe("visibility change and pagehide flush", () => {
it("flushes when document.visibilityState becomes hidden", () => {
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "visibility test" }),
);
// Simulate visibilitychange to hidden
Object.defineProperty(document, "visibilityState", {
value: "hidden",
writable: true,
configurable: true,
});
window.dispatchEvent(new Event("visibilitychange"));
expect(sendBeaconSpy).toHaveBeenCalledTimes(1);
// Restore visibilityState
Object.defineProperty(document, "visibilityState", {
value: "visible",
writable: true,
configurable: true,
});
cleanup();
});
it("does not flush on visibilitychange when state is visible", () => {
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "visible test" }),
);
Object.defineProperty(document, "visibilityState", {
value: "visible",
writable: true,
configurable: true,
});
window.dispatchEvent(new Event("visibilitychange"));
// Should NOT have flushed yet (only periodic timer would flush)
expect(sendBeaconSpy).not.toHaveBeenCalled();
expect(fetchSpy).not.toHaveBeenCalled();
cleanup();
});
it("flushes on pagehide event", () => {
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "pagehide test" }),
);
window.dispatchEvent(new Event("pagehide"));
expect(sendBeaconSpy).toHaveBeenCalledTimes(1);
cleanup();
});
});
// ---------------------------------------------------------------------------
// Cleanup function
// ---------------------------------------------------------------------------
describe("cleanup", () => {
it("removes error event listener", () => {
const removeSpy = vi.spyOn(window, "removeEventListener");
const cleanup = initClientLogger();
cleanup();
const errorRemoves = removeSpy.mock.calls.filter(
([type]) => type === "error",
);
expect(errorRemoves.length).toBe(1);
});
it("removes unhandledrejection event listener", () => {
const removeSpy = vi.spyOn(window, "removeEventListener");
const cleanup = initClientLogger();
cleanup();
const rejectionRemoves = removeSpy.mock.calls.filter(
([type]) => type === "unhandledrejection",
);
expect(rejectionRemoves.length).toBe(1);
});
it("removes pagehide event listener", () => {
const removeSpy = vi.spyOn(window, "removeEventListener");
const cleanup = initClientLogger();
cleanup();
const pageRemoves = removeSpy.mock.calls.filter(
([type]) => type === "pagehide",
);
expect(pageRemoves.length).toBe(1);
});
it("clears the flush interval", () => {
const clearIntervalSpy = vi.spyOn(globalThis, "clearInterval");
const cleanup = initClientLogger();
cleanup();
expect(clearIntervalSpy).toHaveBeenCalled();
});
it("flushes remaining entries on cleanup", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "leftover entry" }),
);
// No timer advance -- just call cleanup directly
cleanup();
// Cleanup calls flush() which tries sendBeacon (false) then fetch
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("leftover entry");
});
it("disconnects PerformanceObserver on cleanup", () => {
const cleanup = initClientLogger();
expect(perfObserverDisconnected).toBe(false);
cleanup();
expect(perfObserverDisconnected).toBe(true);
});
it("no longer captures errors after cleanup", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
cleanup();
// Reset spies after cleanup flush
fetchSpy.mockClear();
sendBeaconSpy.mockClear();
// Dispatch error after cleanup
window.dispatchEvent(
new ErrorEvent("error", { message: "after cleanup" }),
);
vi.advanceTimersByTime(10_000);
// The interval was cleared, so no periodic flush. The event listener was
// removed, so the error was never captured. Nothing should have been sent.
expect(fetchSpy).not.toHaveBeenCalled();
expect(sendBeaconSpy).not.toHaveBeenCalled();
});
});
// ---------------------------------------------------------------------------
// PerformanceObserver integration
// ---------------------------------------------------------------------------
describe("PerformanceObserver integration", () => {
it("observes largest-contentful-paint, paint, and navigation types", () => {
const cleanup = initClientLogger();
expect(perfObserverObservedTypes).toContain("largest-contentful-paint");
expect(perfObserverObservedTypes).toContain("paint");
expect(perfObserverObservedTypes).toContain("navigation");
cleanup();
});
it("captures LCP entries", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
// Simulate PerformanceObserver callback with LCP entry
perfObserverCallback!({
getEntries: () => [
{
entryType: "largest-contentful-paint",
startTime: 1234.5,
name: "largest-contentful-paint",
},
],
});
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].level).toBe("info");
expect(body.entries[0].message).toBe("LCP: 1235ms");
expect(body.entries[0].timing.lcp).toBe(1234.5);
cleanup();
});
it("captures first-contentful-paint entries", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
perfObserverCallback!({
getEntries: () => [
{
entryType: "paint",
startTime: 567.8,
name: "first-contentful-paint",
},
],
});
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("first-contentful-paint: 568ms");
expect(body.entries[0].timing.fcp).toBe(567.8);
cleanup();
});
it("captures first-paint entries with fp timing key", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
perfObserverCallback!({
getEntries: () => [
{
entryType: "paint",
startTime: 200.3,
name: "first-paint",
},
],
});
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries[0].timing.fp).toBe(200.3);
cleanup();
});
it("captures navigation timing entries with TTFB, DOM, and load metrics", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
perfObserverCallback!({
getEntries: () => [
{
entryType: "navigation",
name: "navigation",
startTime: 0,
responseStart: 150.5,
domContentLoadedEventEnd: 450.2,
loadEventEnd: 800.7,
},
],
});
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(1);
expect(body.entries[0].message).toBe("Navigation: TTFB 151ms, DOM 450ms");
expect(body.entries[0].timing.ttfb).toBe(150.5);
expect(body.entries[0].timing.domContentLoaded).toBe(450.2);
expect(body.entries[0].timing.loadComplete).toBe(800.7);
cleanup();
});
it("handles multiple entries in a single observer callback", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
perfObserverCallback!({
getEntries: () => [
{
entryType: "paint",
startTime: 100,
name: "first-paint",
},
{
entryType: "paint",
startTime: 300,
name: "first-contentful-paint",
},
],
});
vi.advanceTimersByTime(10_000);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(2);
expect(body.entries[0].timing.fp).toBe(100);
expect(body.entries[1].timing.fcp).toBe(300);
cleanup();
});
it("gracefully handles PerformanceObserver not being available", () => {
// Remove PerformanceObserver from global scope
// eslint-disable-next-line @typescript-eslint/no-explicit-any
delete (globalThis as any).PerformanceObserver;
const cleanup = initClientLogger();
// Should still work without crashing
expect(typeof cleanup).toBe("function");
// No observer should have been created
expect(perfObserverCallback).toBeNull();
// Restore for subsequent tests
// eslint-disable-next-line @typescript-eslint/no-explicit-any
globalThis.PerformanceObserver = MockPerformanceObserver as any;
cleanup();
});
it("gracefully handles PerformanceObserver.observe throwing", () => {
// Create a mock that throws on observe
// eslint-disable-next-line @typescript-eslint/no-explicit-any
globalThis.PerformanceObserver = class ThrowingObserver {
observe(): void {
throw new Error("not supported");
}
disconnect(): void {
// noop
}
} as any;
// Should not throw
const cleanup = initClientLogger();
expect(typeof cleanup).toBe("function");
// Restore
// eslint-disable-next-line @typescript-eslint/no-explicit-any
globalThis.PerformanceObserver = MockPerformanceObserver as any;
cleanup();
});
});
// ---------------------------------------------------------------------------
// Periodic timer behavior
// ---------------------------------------------------------------------------
describe("periodic timer", () => {
it("flushes every 10 seconds", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
// Add entry and advance 10s
window.dispatchEvent(
new ErrorEvent("error", { message: "tick 1" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
// Add another entry and advance another 10s
window.dispatchEvent(
new ErrorEvent("error", { message: "tick 2" }),
);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(2);
cleanup();
});
it("does not flush at 5 seconds", () => {
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "too early" }),
);
vi.advanceTimersByTime(5_000);
expect(sendBeaconSpy).not.toHaveBeenCalled();
expect(fetchSpy).not.toHaveBeenCalled();
cleanup();
});
});
// ---------------------------------------------------------------------------
// SSR safety
// ---------------------------------------------------------------------------
describe("SSR safety", () => {
it("returns noop cleanup when window is undefined", () => {
// The module checks `typeof window === "undefined"`. In jsdom, window
// always exists so we cannot truly remove it. Instead we verify that the
// function returns a callable cleanup even in the normal path. This test
// documents that the SSR guard exists in the source code.
const cleanup = initClientLogger();
expect(typeof cleanup).toBe("function");
cleanup();
});
});
// ---------------------------------------------------------------------------
// Edge cases
// ---------------------------------------------------------------------------
describe("edge cases", () => {
it("handles error event where error property is null", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
// ErrorEvent with no error object (just a message)
const event = new ErrorEvent("error", {
message: "Script error.",
filename: "",
lineno: 0,
colno: 0,
error: null,
});
window.dispatchEvent(event);
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1);
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries[0].message).toBe("Script error.");
expect(body.entries[0].stack).toBeUndefined();
cleanup();
});
it("handles rapid successive flushes without duplicating entries", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "only once" }),
);
// Trigger flush via pagehide
window.dispatchEvent(new Event("pagehide"));
expect(fetchSpy).toHaveBeenCalledTimes(1);
// Now the periodic timer fires -- buffer should be empty
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalledTimes(1); // Still 1
cleanup();
});
it("payload is valid JSON with entries array", () => {
sendBeaconSpy.mockReturnValue(false);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "json check" }),
);
vi.advanceTimersByTime(10_000);
const rawBody = fetchSpy.mock.calls[0][1].body as string;
const parsed = JSON.parse(rawBody);
expect(parsed).toHaveProperty("entries");
expect(Array.isArray(parsed.entries)).toBe(true);
cleanup();
});
it("sendBeacon receives a Blob with application/json type", () => {
sendBeaconSpy.mockReturnValue(true);
const cleanup = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "blob check" }),
);
vi.advanceTimersByTime(10_000);
const blobArg = sendBeaconSpy.mock.calls[0][1];
expect(blobArg).toBeInstanceOf(Blob);
expect(blobArg.type).toBe("application/json");
cleanup();
});
it("multiple initClientLogger calls share module-level buffer", async () => {
// This test documents that calling initClientLogger multiple times
// accumulates entries into the same buffer. The second cleanup flushes
// entries captured by both instances.
sendBeaconSpy.mockReturnValue(false);
const cleanup1 = initClientLogger();
const cleanup2 = initClientLogger();
window.dispatchEvent(
new ErrorEvent("error", { message: "shared buffer test" }),
);
// Both error listeners fire, so we get 2 entries (one from each init)
vi.advanceTimersByTime(10_000);
expect(fetchSpy).toHaveBeenCalled();
const body = JSON.parse(fetchSpy.mock.calls[0][1].body as string);
expect(body.entries).toHaveLength(2);
cleanup1();
cleanup2();
});
});

View File

@ -0,0 +1,666 @@
/**
* Tests for request-logger: logApiRequest, getRequestStats, normalizePath, percentile.
*/
import { describe, it, expect, vi, beforeEach } from "vitest";
import type { getRequestStats as GetRequestStatsFn } from "../request-logger.js";
// ── Mock fns (hoisted) ────────────────────────────────────────────────
const mockLoadConfig = vi.fn();
const mockGetLogsDir = vi.fn();
const mockReadLogsFromDir = vi.fn();
const mockLogWriterAppend = vi.fn();
const mockLogWriterClose = vi.fn();
vi.mock("@composio/ao-core", () => ({
loadConfig: (...args: unknown[]) => mockLoadConfig(...args),
getLogsDir: (...args: unknown[]) => mockGetLogsDir(...args),
readLogsFromDir: (...args: unknown[]) => mockReadLogsFromDir(...args),
LogWriter: vi.fn().mockImplementation(() => ({
append: mockLogWriterAppend,
appendLine: vi.fn(),
close: mockLogWriterClose,
})),
}));
// ── Import after mocking ──────────────────────────────────────────────
// We need a fresh module for each describe block that tests logApiRequest
// because of the module-level logWriter cache. For getRequestStats tests,
// we can reuse the same import since it doesn't depend on the cached writer.
beforeEach(() => {
vi.clearAllMocks();
});
// ── logApiRequest ─────────────────────────────────────────────────────
describe("logApiRequest", () => {
beforeEach(() => {
vi.resetModules();
// Re-apply mock after resetModules
vi.doMock("@composio/ao-core", () => ({
loadConfig: (...args: unknown[]) => mockLoadConfig(...args),
getLogsDir: (...args: unknown[]) => mockGetLogsDir(...args),
readLogsFromDir: (...args: unknown[]) => mockReadLogsFromDir(...args),
LogWriter: vi.fn().mockImplementation(() => ({
append: mockLogWriterAppend,
appendLine: vi.fn(),
close: mockLogWriterClose,
})),
}));
});
it("logs request with all required fields", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 42,
});
expect(mockLogWriterAppend).toHaveBeenCalledTimes(1);
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.ts).toBe("2026-01-15T10:00:00Z");
expect(entry.level).toBe("info");
expect(entry.source).toBe("api");
expect(entry.sessionId).toBeNull();
expect(entry.message).toBe("GET /api/sessions 200 42ms");
expect(entry.data.method).toBe("GET");
expect(entry.data.path).toBe("/api/sessions");
expect(entry.data.statusCode).toBe(200);
expect(entry.data.durationMs).toBe(42);
});
it("logs error level when error field is present", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "POST",
path: "/api/spawn",
sessionId: null,
statusCode: 500,
durationMs: 100,
error: "spawn failed",
});
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.level).toBe("error");
expect(entry.data.error).toBe("spawn failed");
});
it("includes optional timings field when provided", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
const timings = {
serviceInit: 5,
sessionList: 20,
prEnrichment: 100,
};
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 130,
timings,
});
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.data.timings).toEqual(timings);
});
it("includes optional cacheStats field when provided", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
const cacheStats = { hits: 5, misses: 2, hitRate: 0.71, size: 10 };
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 50,
cacheStats,
});
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.data.cacheStats).toEqual(cacheStats);
});
it("omits optional fields from data when not provided", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 42,
});
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.data).not.toHaveProperty("error");
expect(entry.data).not.toHaveProperty("timings");
expect(entry.data).not.toHaveProperty("cacheStats");
});
it("handles missing logDir gracefully (no projects)", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: {},
});
const { logApiRequest } = await import("../request-logger.js");
// Should not throw
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 42,
});
expect(mockLogWriterAppend).not.toHaveBeenCalled();
});
it("handles loadConfig throwing an error gracefully", async () => {
mockLoadConfig.mockImplementation(() => {
throw new Error("No config file found");
});
const { logApiRequest } = await import("../request-logger.js");
// Should not throw
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 42,
});
expect(mockLogWriterAppend).not.toHaveBeenCalled();
});
it("caches the LogWriter after first successful initialization", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 42,
});
logApiRequest({
ts: "2026-01-15T10:01:00Z",
method: "GET",
path: "/api/sessions",
sessionId: null,
statusCode: 200,
durationMs: 55,
});
// loadConfig should only be called once (writer is cached)
expect(mockLoadConfig).toHaveBeenCalledTimes(1);
// But append should be called twice
expect(mockLogWriterAppend).toHaveBeenCalledTimes(2);
});
it("includes sessionId in log entry", async () => {
mockLoadConfig.mockReturnValue({
configPath: "/tmp/config.yaml",
projects: { myProject: { path: "/tmp/project" } },
});
mockGetLogsDir.mockReturnValue("/tmp/logs");
const { logApiRequest } = await import("../request-logger.js");
logApiRequest({
ts: "2026-01-15T10:00:00Z",
method: "GET",
path: "/api/sessions/ao-5",
sessionId: "ao-5",
statusCode: 200,
durationMs: 42,
});
const entry = mockLogWriterAppend.mock.calls[0][0];
expect(entry.sessionId).toBe("ao-5");
});
});
// ── getRequestStats ───────────────────────────────────────────────────
describe("getRequestStats", () => {
// getRequestStats calls readLogsFromDir directly, no cached writer involved
let getRequestStats: GetRequestStatsFn;
beforeEach(async () => {
vi.resetModules();
vi.doMock("@composio/ao-core", () => ({
loadConfig: (...args: unknown[]) => mockLoadConfig(...args),
getLogsDir: (...args: unknown[]) => mockGetLogsDir(...args),
readLogsFromDir: (...args: unknown[]) => mockReadLogsFromDir(...args),
LogWriter: vi.fn().mockImplementation(() => ({
append: mockLogWriterAppend,
appendLine: vi.fn(),
close: mockLogWriterClose,
})),
}));
const mod = await import("../request-logger.js");
getRequestStats = mod.getRequestStats;
});
it("computes per-route stats with count, avgMs, percentiles", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
makeLogEntry("GET", "/api/sessions", 200, 200),
makeLogEntry("GET", "/api/sessions", 200, 300),
makeLogEntry("GET", "/api/sessions", 200, 400),
]);
const result = getRequestStats("/tmp/logs");
const route = result.routes["GET /api/sessions"];
expect(route).toBeDefined();
expect(route.count).toBe(4);
expect(route.avgMs).toBe(250); // (100+200+300+400)/4
expect(route.errors).toBe(0);
});
it("counts errors when statusCode >= 400", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
makeLogEntry("GET", "/api/sessions", 400, 50),
makeLogEntry("GET", "/api/sessions", 500, 200),
]);
const result = getRequestStats("/tmp/logs");
const route = result.routes["GET /api/sessions"];
expect(route.errors).toBe(2);
});
it("counts errors when error field is present", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("POST", "/api/spawn", 200, 100, "something went wrong"),
]);
const result = getRequestStats("/tmp/logs");
const route = result.routes["POST /api/spawn"];
expect(route.errors).toBe(1);
});
it("groups by normalized path (dynamic segments replaced)", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions/abc123", 200, 100),
makeLogEntry("GET", "/api/sessions/def456", 200, 200),
makeLogEntry("GET", "/api/prs/42/merge", 200, 50),
makeLogEntry("GET", "/api/prs/99/merge", 200, 150),
]);
const result = getRequestStats("/tmp/logs");
// Both session paths should be grouped under :id
expect(result.routes["GET /api/sessions/:id"]).toBeDefined();
expect(result.routes["GET /api/sessions/:id"].count).toBe(2);
// Both PR paths should be grouped under :id
expect(result.routes["GET /api/prs/:id/merge"]).toBeDefined();
expect(result.routes["GET /api/prs/:id/merge"].count).toBe(2);
// Original paths should NOT exist as separate routes
expect(result.routes["GET /api/sessions/abc123"]).toBeUndefined();
expect(result.routes["GET /api/prs/42/merge"]).toBeUndefined();
});
it("returns slowest requests sorted by duration (descending)", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 50),
makeLogEntry("GET", "/api/sessions", 200, 3000),
makeLogEntry("GET", "/api/sessions", 200, 500),
]);
const result = getRequestStats("/tmp/logs");
expect(result.slowest).toHaveLength(3);
expect(result.slowest[0].durationMs).toBe(3000);
expect(result.slowest[1].durationMs).toBe(500);
expect(result.slowest[2].durationMs).toBe(50);
});
it("limits slowest to 10 entries", () => {
const entries = [];
for (let i = 0; i < 15; i++) {
entries.push(makeLogEntry("GET", "/api/sessions", 200, (i + 1) * 10));
}
mockReadLogsFromDir.mockReturnValue(entries);
const result = getRequestStats("/tmp/logs");
expect(result.slowest).toHaveLength(10);
// The slowest should be 150ms (15*10), not 10ms (1*10)
expect(result.slowest[0].durationMs).toBe(150);
});
it("handles empty log directory (no entries)", () => {
mockReadLogsFromDir.mockReturnValue([]);
const result = getRequestStats("/tmp/logs");
expect(result.routes).toEqual({});
expect(result.slowest).toEqual([]);
});
it("passes since filter to readLogsFromDir", () => {
mockReadLogsFromDir.mockReturnValue([]);
const since = new Date("2026-01-15T00:00:00Z");
getRequestStats("/tmp/logs", { since });
expect(mockReadLogsFromDir).toHaveBeenCalledWith(
"/tmp/logs",
"api",
expect.objectContaining({ since }),
);
});
it("filters by route pattern", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
makeLogEntry("GET", "/api/prs", 200, 200),
makeLogEntry("POST", "/api/sessions/abc/kill", 200, 50),
]);
const result = getRequestStats("/tmp/logs", { route: "sessions" });
// Only routes containing "sessions" should be included
expect(Object.keys(result.routes)).toEqual(
expect.arrayContaining(["GET /api/sessions"]),
);
expect(result.routes["GET /api/prs"]).toBeUndefined();
expect(result.slowest.every((r) => r.path.includes("sessions"))).toBe(true);
});
it("skips entries without method or path in data", () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-01-15T10:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "some log without method/path",
data: { statusCode: 200, durationMs: 50 },
},
makeLogEntry("GET", "/api/sessions", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(Object.keys(result.routes)).toHaveLength(1);
expect(result.routes["GET /api/sessions"].count).toBe(1);
});
it("handles entries with missing data object", () => {
mockReadLogsFromDir.mockReturnValue([
{
ts: "2026-01-15T10:00:00Z",
level: "info",
source: "api",
sessionId: null,
message: "bare entry",
},
makeLogEntry("GET", "/api/sessions", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(Object.keys(result.routes)).toHaveLength(1);
});
it("separates routes by HTTP method", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
makeLogEntry("POST", "/api/sessions", 201, 200),
]);
const result = getRequestStats("/tmp/logs");
expect(result.routes["GET /api/sessions"]).toBeDefined();
expect(result.routes["POST /api/sessions"]).toBeDefined();
expect(result.routes["GET /api/sessions"].count).toBe(1);
expect(result.routes["POST /api/sessions"].count).toBe(1);
});
});
// ── normalizePath (tested indirectly via getRequestStats) ─────────────
describe("normalizePath (indirect)", () => {
let getRequestStats: GetRequestStatsFn;
beforeEach(async () => {
vi.resetModules();
vi.doMock("@composio/ao-core", () => ({
loadConfig: (...args: unknown[]) => mockLoadConfig(...args),
getLogsDir: (...args: unknown[]) => mockGetLogsDir(...args),
readLogsFromDir: (...args: unknown[]) => mockReadLogsFromDir(...args),
LogWriter: vi.fn().mockImplementation(() => ({
append: mockLogWriterAppend,
appendLine: vi.fn(),
close: mockLogWriterClose,
})),
}));
const mod = await import("../request-logger.js");
getRequestStats = mod.getRequestStats;
});
it("/api/sessions/abc123 normalizes to /api/sessions/:id", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions/abc123", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(result.routes["GET /api/sessions/:id"]).toBeDefined();
});
it("/api/prs/42/merge normalizes to /api/prs/:id/merge", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/prs/42/merge", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(result.routes["GET /api/prs/:id/merge"]).toBeDefined();
});
it("/api/sessions remains unchanged (no dynamic segment)", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(result.routes["GET /api/sessions"]).toBeDefined();
});
it("normalizes multiple dynamic segments in one path", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions/abc123/prs/42", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
// sessions/:id and prs/:id should both be replaced
expect(result.routes["GET /api/sessions/:id/prs/:id"]).toBeDefined();
});
it("non-matching paths remain unchanged", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/config", 200, 100),
]);
const result = getRequestStats("/tmp/logs");
expect(result.routes["GET /api/config"]).toBeDefined();
});
});
// ── percentile (tested indirectly via getRequestStats) ────────────────
describe("percentile (indirect)", () => {
let getRequestStats: GetRequestStatsFn;
beforeEach(async () => {
vi.resetModules();
vi.doMock("@composio/ao-core", () => ({
loadConfig: (...args: unknown[]) => mockLoadConfig(...args),
getLogsDir: (...args: unknown[]) => mockGetLogsDir(...args),
readLogsFromDir: (...args: unknown[]) => mockReadLogsFromDir(...args),
LogWriter: vi.fn().mockImplementation(() => ({
append: mockLogWriterAppend,
appendLine: vi.fn(),
close: mockLogWriterClose,
})),
}));
const mod = await import("../request-logger.js");
getRequestStats = mod.getRequestStats;
});
it("returns 0 for empty array (no entries)", () => {
mockReadLogsFromDir.mockReturnValue([]);
const result = getRequestStats("/tmp/logs");
// No routes means no percentiles to check, but verify no crash
expect(result.routes).toEqual({});
});
it("returns the single element for single-entry route", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 42),
]);
const result = getRequestStats("/tmp/logs");
const route = result.routes["GET /api/sessions"];
expect(route.p50Ms).toBe(42);
expect(route.p95Ms).toBe(42);
expect(route.p99Ms).toBe(42);
});
it("computes correct p50 for two elements", () => {
mockReadLogsFromDir.mockReturnValue([
makeLogEntry("GET", "/api/sessions", 200, 100),
makeLogEntry("GET", "/api/sessions", 200, 200),
]);
const result = getRequestStats("/tmp/logs");
const route = result.routes["GET /api/sessions"];
// sorted: [100, 200]
// p50: ceil(50/100 * 2) - 1 = ceil(1) - 1 = 0 => sorted[0] = 100
expect(route.p50Ms).toBe(100);
// p95: ceil(95/100 * 2) - 1 = ceil(1.9) - 1 = 1 => sorted[1] = 200
expect(route.p95Ms).toBe(200);
// p99: ceil(99/100 * 2) - 1 = ceil(1.98) - 1 = 1 => sorted[1] = 200
expect(route.p99Ms).toBe(200);
});
it("computes correct percentiles for a larger dataset", () => {
// 100 entries with durations 1..100
const entries = [];
for (let i = 1; i <= 100; i++) {
entries.push(makeLogEntry("GET", "/api/sessions", 200, i));
}
mockReadLogsFromDir.mockReturnValue(entries);
const result = getRequestStats("/tmp/logs");
const route = result.routes["GET /api/sessions"];
expect(route.count).toBe(100);
// p50: ceil(50/100 * 100) - 1 = 50 - 1 = 49 => sorted[49] = 50
expect(route.p50Ms).toBe(50);
// p95: ceil(95/100 * 100) - 1 = 95 - 1 = 94 => sorted[94] = 95
expect(route.p95Ms).toBe(95);
// p99: ceil(99/100 * 100) - 1 = 99 - 1 = 98 => sorted[98] = 99
expect(route.p99Ms).toBe(99);
expect(route.avgMs).toBe(51); // Math.round(5050 / 100) = 51 (rounded up from 50.5)
});
});
// ── Helpers ───────────────────────────────────────────────────────────
function makeLogEntry(
method: string,
path: string,
statusCode: number,
durationMs: number,
error?: string,
) {
return {
ts: "2026-01-15T10:00:00Z",
level: error ? "error" : "info",
source: "api",
sessionId: null,
message: `${method} ${path} ${statusCode} ${durationMs}ms`,
data: {
method,
path,
statusCode,
durationMs,
...(error && { error }),
},
};
}

View File

@ -0,0 +1,348 @@
/**
* Tests for with-timing: withTiming, extractSessionId, createTimingContext.
*/
import { describe, it, expect, vi, beforeEach } from "vitest";
// ── Mock logApiRequest from request-logger ────────────────────────────
const mockLogApiRequest = vi.fn();
vi.mock("../request-logger.js", () => ({
logApiRequest: (...args: unknown[]) => mockLogApiRequest(...args),
}));
// ── Import after mocking ──────────────────────────────────────────────
import { withTiming, createTimingContext } from "../with-timing.js";
beforeEach(() => {
vi.clearAllMocks();
});
// ── withTiming ────────────────────────────────────────────────────────
describe("withTiming", () => {
it("wraps handler and calls it with the request", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response(JSON.stringify({ ok: true }), { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
await wrapped(req);
expect(innerHandler).toHaveBeenCalledTimes(1);
expect(innerHandler).toHaveBeenCalledWith(req, undefined);
});
it("passes context argument through to handler", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const ctx = { params: { id: "abc" } };
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions/abc");
await wrapped(req, ctx);
expect(innerHandler).toHaveBeenCalledWith(req, ctx);
});
it("returns the original response unchanged on success", async () => {
const body = JSON.stringify({ sessions: [] });
const originalResponse = new Response(body, {
status: 200,
headers: { "Content-Type": "application/json" },
});
const innerHandler = vi.fn().mockResolvedValue(originalResponse);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
const result = await wrapped(req);
expect(result).toBe(originalResponse);
expect(result.status).toBe(200);
});
it("calls logApiRequest with correct fields for successful response", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
await wrapped(req);
expect(mockLogApiRequest).toHaveBeenCalledTimes(1);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.method).toBe("GET");
expect(log.path).toBe("/api/sessions");
expect(log.statusCode).toBe(200);
expect(typeof log.durationMs).toBe("number");
expect(log.durationMs).toBeGreaterThanOrEqual(0);
expect(log.error).toBeUndefined();
expect(log.ts).toBeDefined();
expect(typeof log.ts).toBe("string");
});
it("logs correct method for POST requests", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("created", { status: 201 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/spawn", {
method: "POST",
body: JSON.stringify({ session: "ao-1" }),
});
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.method).toBe("POST");
expect(log.statusCode).toBe(201);
});
it("logs error responses (4xx) without error field", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("not found", { status: 404 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions/unknown");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.statusCode).toBe(404);
// error field is only set when the handler throws, not for error status codes
expect(log.error).toBeUndefined();
});
it("logs error responses (5xx) without error field when handler does not throw", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("internal error", { status: 500 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.statusCode).toBe(500);
expect(log.error).toBeUndefined();
});
it("catches thrown errors, logs them, and returns 500 response", async () => {
const innerHandler = vi.fn().mockRejectedValue(
new Error("database connection failed"),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
const result = await wrapped(req);
// Should return a 500 response with the error
expect(result.status).toBe(500);
const body = await result.json();
expect(body.error).toBe("database connection failed");
// Should have logged the error
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.statusCode).toBe(500);
expect(log.error).toBe("database connection failed");
});
it("handles non-Error thrown values", async () => {
const innerHandler = vi.fn().mockRejectedValue("string error");
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
const result = await wrapped(req);
expect(result.status).toBe(500);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.error).toBe("string error");
});
it("measures duration (durationMs is non-negative)", async () => {
const innerHandler = vi.fn().mockImplementation(async () => {
// Simulate some work
await new Promise((resolve) => setTimeout(resolve, 10));
return new Response("ok", { status: 200 });
});
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.durationMs).toBeGreaterThanOrEqual(0);
});
});
// ── extractSessionId (tested indirectly via withTiming) ───────────────
describe("extractSessionId (indirect via withTiming)", () => {
it("extracts sessionId from /api/sessions/abc123", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions/abc123");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBe("abc123");
});
it("extracts sessionId from /api/sessions/ao-1/kill", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions/ao-1/kill");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBe("ao-1");
});
it("returns null for /api/sessions (no ID segment)", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/sessions");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBeNull();
});
it("returns null for /api/prs/42/merge (no sessions segment)", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/prs/42/merge");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBeNull();
});
it("returns null for /api/config (no sessions segment)", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request("http://localhost:3000/api/config");
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBeNull();
});
it("decodes URL-encoded session IDs", async () => {
const innerHandler = vi.fn().mockResolvedValue(
new Response("ok", { status: 200 }),
);
const wrapped = withTiming(innerHandler, "test-route");
const req = new Request(
"http://localhost:3000/api/sessions/session%20with%20spaces",
);
await wrapped(req);
const log = mockLogApiRequest.mock.calls[0][0];
expect(log.sessionId).toBe("session with spaces");
});
});
// ── createTimingContext ───────────────────────────────────────────────
describe("createTimingContext", () => {
it("creates context with empty timings object", () => {
const ctx = createTimingContext();
expect(ctx.timings).toEqual({});
});
it("creates context with a start timestamp", () => {
const before = Date.now();
const ctx = createTimingContext();
const after = Date.now();
expect(ctx.start).toBeGreaterThanOrEqual(before);
expect(ctx.start).toBeLessThanOrEqual(after);
});
it("has a mark function", () => {
const ctx = createTimingContext();
expect(typeof ctx.mark).toBe("function");
});
it("mark() records operation timing with name and duration", () => {
const ctx = createTimingContext();
const opStart = Date.now() - 50; // Simulate 50ms ago
ctx.mark("serviceInit", opStart);
expect(ctx.timings["serviceInit"]).toBeDefined();
expect(ctx.timings["serviceInit"]).toBeGreaterThanOrEqual(49); // allow 1ms slack
});
it("mark() can record multiple operations", () => {
const ctx = createTimingContext();
const start1 = Date.now() - 100;
ctx.mark("serviceInit", start1);
const start2 = Date.now() - 50;
ctx.mark("sessionList", start2);
const start3 = Date.now() - 25;
ctx.mark("prEnrichment", start3);
expect(Object.keys(ctx.timings)).toHaveLength(3);
expect(ctx.timings["serviceInit"]).toBeDefined();
expect(ctx.timings["sessionList"]).toBeDefined();
expect(ctx.timings["prEnrichment"]).toBeDefined();
});
it("mark() overwrites previous timing for same operation name", () => {
const ctx = createTimingContext();
const start1 = Date.now() - 100;
ctx.mark("serviceInit", start1);
const first = ctx.timings["serviceInit"];
const start2 = Date.now() - 10;
ctx.mark("serviceInit", start2);
const second = ctx.timings["serviceInit"];
// Second mark should record a shorter duration
expect(second).toBeLessThan(first);
});
it("mark() computes duration as Date.now() - startMs", () => {
vi.useFakeTimers();
vi.setSystemTime(new Date("2026-01-15T10:00:00.100Z"));
const ctx = createTimingContext();
// Simulate an operation that started at T=0
const opStart = new Date("2026-01-15T10:00:00.000Z").getTime();
// Advance to T=100ms for mark
ctx.mark("serviceInit", opStart);
expect(ctx.timings["serviceInit"]).toBe(100);
vi.useRealTimers();
});
});