diff --git a/packages/cli/__tests__/lib/perf-utils.test.ts b/packages/cli/__tests__/lib/perf-utils.test.ts index f5410af29..7dad684f4 100644 --- a/packages/cli/__tests__/lib/perf-utils.test.ts +++ b/packages/cli/__tests__/lib/perf-utils.test.ts @@ -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; + }>; + 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 | 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, diff --git a/packages/cli/src/lib/perf-utils.ts b/packages/cli/src/lib/perf-utils.ts index 9f4414ed7..ce9d12a62 100644 --- a/packages/cli/src/lib/perf-utils.ts +++ b/packages/cli/src/lib/perf-utils.ts @@ -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; - 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 | 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); } diff --git a/packages/core/src/__tests__/dashboard-manager.test.ts b/packages/core/src/__tests__/dashboard-manager.test.ts new file mode 100644 index 000000000..c34c85693 --- /dev/null +++ b/packages/core/src/__tests__/dashboard-manager.test.ts @@ -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 { + 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 { + 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 }); + }); +}); diff --git a/packages/core/src/__tests__/lifecycle-manager.test.ts b/packages/core/src/__tests__/lifecycle-manager.test.ts index b096fdeab..940b85bd4 100644 --- a/packages/core/src/__tests__/lifecycle-manager.test.ts +++ b/packages/core/src/__tests__/lifecycle-manager.test.ts @@ -866,3 +866,2036 @@ describe("getStates", () => { expect(lm.getStates().get("app-1")).toBe("working"); }); }); + +// ============================================================================= +// Helper functions tested indirectly through the public API +// ============================================================================= + +describe("inferPriority (tested indirectly via notification routing)", () => { + /** + * inferPriority maps event types to priorities: + * - "stuck"/"needs_input"/"errored" → "urgent" + * - "approved"/"ready"/"merged"/"completed" → "action" + * - "fail"/"changes_requested"/"conflicts" → "warning" + * - "summary.*" → "info" + * - everything else → "info" + * + * We test this by observing which notifiers get called based on + * notificationRouting config for different priority levels. + */ + + it("routes 'urgent' priority for stuck transitions", async () => { + const urgentNotifier: Notifier = { + name: "urgent-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "urgent-channel") return urgentNotifier; + return null; + }), + }; + + // Configure: only "urgent-channel" receives "urgent" priority + const urgentConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["urgent-channel"], + action: [], + warning: [], + info: [], + }, + reactions: {}, + }; + + // session.stuck has no reaction key mapping, so it should hit notifyHuman + // inferPriority("session.stuck") → "urgent" + // The session needs_input → stuck transition won't happen directly, + // but working → needs_input triggers "session.needs_input" → "urgent" + vi.mocked(mockAgent.detectActivity).mockReturnValue("waiting_input"); + + const session = makeSession({ status: "working" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: urgentConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("needs_input"); + // session.needs_input maps to "agent-needs-input" reaction key, + // but there's no reaction configured, so it should notify. + // inferPriority("session.needs_input") includes "needs_input" → "urgent" + expect(urgentNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "session.needs_input", + priority: "urgent", + }), + ); + }); + + it("routes 'warning' priority for ci.failing (no reaction configured)", async () => { + const warningNotifier: Notifier = { + name: "warning-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "warning-channel") return warningNotifier; + return null; + }), + }; + + const warningConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: [], + action: [], + warning: ["warning-channel"], + info: [], + }, + reactions: {}, // No reaction for ci-failed, so it falls through to notifyHuman + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: warningConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("ci_failed"); + // inferPriority("ci.failing") includes "fail" → "warning" + expect(warningNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "ci.failing", + priority: "warning", + }), + ); + }); + + it("routes 'action' priority for merge.completed", async () => { + const actionNotifier: Notifier = { + name: "action-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("merged"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn(), + getReviews: vi.fn(), + getReviewDecision: vi.fn(), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "action-channel") return actionNotifier; + return null; + }), + }; + + const actionConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: [], + action: ["action-channel"], + warning: [], + info: [], + }, + reactions: {}, + }; + + const session = makeSession({ status: "approved", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "approved", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: actionConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("merged"); + // inferPriority("merge.completed") includes "completed" → "action" + expect(actionNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "merge.completed", + priority: "action", + }), + ); + }); + + it("does not notify for 'info' priority transitions when no notifiers configured for info", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + // session.working → inferPriority("session.working") = "info" (no special keywords) + const session = makeSession({ status: "spawning" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "spawning", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, // default config has info: [] + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("working"); + // "session.working" → "info" priority → should NOT notify (info is not > info) + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); +}); + +describe("statusToEventType (tested indirectly via check transitions)", () => { + /** + * statusToEventType maps session status to event types. + * We verify by checking which event type reaches the notifier. + */ + + it("maps 'review_pending' status to 'review.pending' event (info priority, not notified)", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("passing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("pending"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const notifyConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: notifyConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // pr_open → review_pending correctly maps to "review.pending" event type + expect(lm.getStates().get("app-1")).toBe("review_pending"); + // inferPriority("review.pending") = "info" (no special keywords matched) + // The code only calls notifyHuman when priority !== "info", so no notification fires. + // This verifies that review.pending is correctly classified as info-level. + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); + + it("maps 'changes_requested' status to 'review.changes_requested' event", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("passing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("changes_requested"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const notifyConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + // No reaction for changes-requested, so notification will fire directly + reactions: {}, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: notifyConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("changes_requested"); + // review.changes_requested has reaction key "changes-requested", but no reaction + // configured, so notifyHuman fires directly. + // inferPriority("review.changes_requested") → "warning" (contains "changes_requested") + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "review.changes_requested", + priority: "warning", + }), + ); + }); + + it("returns null event type for 'spawning' status (no notification)", async () => { + // When a session remains in "spawning" status, statusToEventType returns null for + // spawning, so no event or notification is fired. + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + // For spawning → working, the event type is "session.working" (the TO status). + // But if we have a status that maps to null... that's only "spawning" as the TO value, + // which doesn't happen in normal flow. Instead, verify spawning → working produces + // session.working (not null), confirming the switch on the TO status. + const session = makeSession({ status: "spawning" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "spawning", + project: "my-app", + }); + + const notifyConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + }; + + const lm = createLifecycleManager({ + config: notifyConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // spawning → working; "session.working" → inferPriority = "info" + // info priority is not > info, so no notification is sent + expect(lm.getStates().get("app-1")).toBe("working"); + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); +}); + +describe("eventToReactionKey (tested indirectly via reaction triggering)", () => { + /** + * eventToReactionKey maps event types to reaction config keys. + * We verify by configuring reactions with specific keys and + * checking they fire on the correct transitions. + */ + + it("maps review.changes_requested to 'changes-requested' reaction key", async () => { + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("passing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("changes_requested"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithSCM: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + return null; + }), + }; + + const reactionConfig: OrchestratorConfig = { + ...config, + reactions: { + "changes-requested": { + auto: true, + action: "send-to-agent", + message: "Address the review feedback.", + retries: 3, + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: reactionConfig, + registry: registryWithSCM, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("changes_requested"); + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Address the review feedback."); + }); + + it("maps merge.ready to 'approved-and-green' reaction key", async () => { + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("passing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("approved"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn().mockResolvedValue({ + mergeable: true, + ciPassing: true, + approved: true, + noConflicts: true, + blockers: [], + }), + }; + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithSCM: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const reactionConfig: OrchestratorConfig = { + ...config, + reactions: { + "approved-and-green": { + auto: true, + action: "auto-merge", + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: reactionConfig, + registry: registryWithSCM, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("mergeable"); + // auto-merge reaction calls notifyHuman internally with "action" priority + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "reaction.triggered", + priority: "action", + }), + ); + }); + + it("maps session.killed to 'agent-exited' reaction key", async () => { + vi.mocked(mockRuntime.isAlive).mockResolvedValue(false); + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const reactionConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "agent-exited": { + auto: true, + action: "notify", + priority: "warning", + }, + }, + }; + + const session = makeSession({ status: "working" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: reactionConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("killed"); + // agent-exited reaction with action="notify" calls notifyHuman with + // the configured priority ("warning") + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "reaction.triggered", + priority: "warning", + }), + ); + }); + + it("falls through to direct notification for events without reaction keys", async () => { + // "review.approved" maps to "approved" status, event type "review.approved" + // eventToReactionKey does NOT have a mapping for "review.approved" + // (only "merge.ready" → "approved-and-green") + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("passing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("approved"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn().mockResolvedValue({ + mergeable: false, + ciPassing: true, + approved: true, + noConflicts: true, + blockers: ["branch protection"], + }), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const notifyConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: notifyConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // Approved but not mergeable → "approved" status + expect(lm.getStates().get("app-1")).toBe("approved"); + // review.approved has no reaction key → falls to notifyHuman + // inferPriority("review.approved") → "action" (contains "approved") + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "review.approved", + priority: "action", + }), + ); + }); +}); + +describe("createEvent (tested indirectly via notifier arguments)", () => { + it("populates all event fields including auto-inferred priority", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("merged"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn(), + getReviews: vi.fn(), + getReviewDecision: vi.fn(), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const notifyConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + }; + + const session = makeSession({ status: "approved", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "approved", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: notifyConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(mockNotifier.notify).toHaveBeenCalledTimes(1); + const event = vi.mocked(mockNotifier.notify).mock.calls[0][0]; + + // Verify all createEvent fields are populated + expect(event.id).toBeDefined(); + expect(typeof event.id).toBe("string"); + expect(event.id.length).toBeGreaterThan(0); + expect(event.type).toBe("merge.completed"); + expect(event.priority).toBe("action"); // auto-inferred: "completed" → "action" + expect(event.sessionId).toBe("app-1"); + expect(event.projectId).toBe("my-app"); + expect(event.timestamp).toBeInstanceOf(Date); + expect(event.message).toContain("app-1"); + expect(event.message).toContain("approved"); + expect(event.message).toContain("merged"); + expect(event.data).toEqual( + expect.objectContaining({ + oldStatus: "approved", + newStatus: "merged", + }), + ); + }); +}); + +describe("parseDuration (tested indirectly via escalation logic)", () => { + /** + * parseDuration is used in executeReaction to compare escalateAfter + * duration strings against elapsed time. We test it by configuring + * escalateAfter with various duration strings and checking escalation. + */ + + it("does not time-escalate on first attempt even with short duration (tracker is fresh)", async () => { + // parseDuration("1h") = 3_600_000ms. Even with escalateAfter="1h", + // the first attempt won't trigger time-based escalation because no time + // has elapsed since firstTriggered. This verifies parseDuration("1h") is + // parsed correctly and the elapsed time comparison works. + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const escalationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 100, + escalateAfter: "1h", // 3_600_000ms — won't be exceeded on first attempt + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: escalationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // Should send to agent normally, no escalation + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); + + it("parses '30s' duration correctly (escalation not triggered within 30s)", async () => { + // Verifies parseDuration("30s") = 30_000ms by configuring escalateAfter="30s" + // and confirming no escalation on the first attempt (elapsed time ~ 0ms < 30_000ms) + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const escalationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 100, + escalateAfter: "30s", // 30_000ms + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: escalationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // First attempt, no time elapsed: should send to agent, not escalate + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); + + it("does not escalate when duration has not elapsed", async () => { + vi.useFakeTimers(); + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const escalationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 100, + escalateAfter: "10m", // 10 minutes — won't elapse in this test + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: escalationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + // Trigger first check: pr_open → ci_failed + await lm.check("app-1"); + + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + // Should NOT have escalated — only 0ms elapsed vs 10m threshold + expect(mockNotifier.notify).not.toHaveBeenCalled(); + + vi.useRealTimers(); + }); + + it("treats invalid duration format as 0 (no time-based escalation)", async () => { + // parseDuration returns 0 for invalid formats. When escalateAfter = "invalid", + // durationMs = 0, and the condition `durationMs > 0` prevents time-based escalation. + // Only numeric retry-based escalation applies. + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const invalidDurationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 100, + escalateAfter: "invalid", // parseDuration returns 0 → durationMs > 0 is false + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: invalidDurationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // Should send to agent (not escalate), because invalid duration = 0 = no time escalation + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + expect(mockNotifier.notify).not.toHaveBeenCalled(); + }); +}); + +describe("pollAll (tested via start/stop with fake timers)", () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it("polls all active sessions on each interval tick", async () => { + const sessions = [ + makeSession({ id: "app-1", status: "working" }), + makeSession({ id: "app-2", status: "spawning" }), + ]; + + vi.mocked(mockSessionManager.list).mockResolvedValue(sessions); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + writeMetadata(sessionsDir, "app-2", { + worktree: "/tmp", + branch: "feat/new", + status: "spawning", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + + // Wait for initial pollAll to complete + await vi.advanceTimersByTimeAsync(0); + + expect(mockSessionManager.list).toHaveBeenCalledTimes(1); + + // After one interval + await vi.advanceTimersByTimeAsync(5000); + expect(mockSessionManager.list).toHaveBeenCalledTimes(2); + + // After another interval + await vi.advanceTimersByTimeAsync(5000); + expect(mockSessionManager.list).toHaveBeenCalledTimes(3); + + lm.stop(); + }); + + it("skips terminal sessions (merged, killed) unless state changed from tracked", async () => { + const sessions = [ + makeSession({ id: "app-1", status: "merged" }), + makeSession({ id: "app-2", status: "killed" }), + makeSession({ id: "app-3", status: "working" }), + ]; + + vi.mocked(mockSessionManager.list).mockResolvedValue(sessions); + + writeMetadata(sessionsDir, "app-3", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + const states = lm.getStates(); + // app-3 is working and should have been polled + expect(states.get("app-3")).toBe("working"); + // app-1 and app-2 are terminal with no tracked state diff, so they were skipped. + // They may or may not appear in states depending on the filter, but they should not + // have caused determineStatus calls. Since they're filtered out, they shouldn't + // appear in states at all (checkSession is never called for them). + expect(states.has("app-1")).toBe(false); + expect(states.has("app-2")).toBe(false); + + lm.stop(); + }); + + it("processes terminal sessions when tracked state differs from list() status", async () => { + // Simulate: session was previously tracked as "working" but list() now returns "killed" + // (e.g., runtime died and list() detected it) + const session = makeSession({ id: "app-1", status: "working" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + // First: track the session as "working" via check + await lm.check("app-1"); + expect(lm.getStates().get("app-1")).toBe("working"); + + // Now list() returns it as "killed" — the session filter should include it + // because tracked state ("working") differs from list status ("killed") + const killedSession = makeSession({ id: "app-1", status: "killed" }); + vi.mocked(mockSessionManager.list).mockResolvedValue([killedSession]); + vi.mocked(mockRuntime.isAlive).mockResolvedValue(false); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + // The session should now be tracked as "killed" after poll + expect(lm.getStates().get("app-1")).toBe("killed"); + + lm.stop(); + }); + + it("handles errors in individual sessions without stopping the poll", async () => { + // Set up two sessions: app-1 will have an error config, app-2 should still be processed + const session1 = makeSession({ + id: "app-1", + status: "working", + runtimeHandle: { id: "rt-err", runtimeName: "mock", data: {} }, + }); + const session2 = makeSession({ + id: "app-2", + status: "spawning", + runtimeHandle: { id: "rt-ok", runtimeName: "mock", data: {} }, + }); + + vi.mocked(mockSessionManager.list).mockResolvedValue([session1, session2]); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + writeMetadata(sessionsDir, "app-2", { + worktree: "/tmp", + branch: "feat/new", + status: "spawning", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + // app-2 should have been polled successfully even if app-1 had issues + // (pollAll uses Promise.allSettled) + const states = lm.getStates(); + expect(states.get("app-2")).toBe("working"); // spawning → working + + lm.stop(); + }); + + it("prunes stale entries from states map for removed sessions", async () => { + const session = makeSession({ id: "app-1", status: "working" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "working", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + // Track a session via check() + await lm.check("app-1"); + expect(lm.getStates().has("app-1")).toBe(true); + + // Now list returns no sessions (session was cleaned up externally) + vi.mocked(mockSessionManager.list).mockResolvedValue([]); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + // The stale entry should be pruned + expect(lm.getStates().has("app-1")).toBe(false); + + lm.stop(); + }); + + it("emits all-complete reaction when all sessions become terminal", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const allCompleteConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "all-complete": { + auto: true, + action: "notify", + priority: "action", + }, + }, + }; + + // All sessions are terminal + const sessions = [ + makeSession({ id: "app-1", status: "merged" }), + makeSession({ id: "app-2", status: "killed" }), + ]; + + vi.mocked(mockSessionManager.list).mockResolvedValue(sessions); + + const lm = createLifecycleManager({ + config: allCompleteConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + // all-complete reaction should have been triggered + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "reaction.triggered", + }), + ); + + lm.stop(); + }); + + it("does not emit all-complete twice for the same terminal state", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const allCompleteConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "all-complete": { + auto: true, + action: "notify", + priority: "action", + }, + }, + }; + + const sessions = [makeSession({ id: "app-1", status: "merged" })]; + vi.mocked(mockSessionManager.list).mockResolvedValue(sessions); + + const lm = createLifecycleManager({ + config: allCompleteConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + const callCount = vi.mocked(mockNotifier.notify).mock.calls.length; + + // Second poll tick + await vi.advanceTimersByTimeAsync(5000); + + // Should not have been called again + expect(mockNotifier.notify).toHaveBeenCalledTimes(callCount); + + lm.stop(); + }); + + it("does not emit all-complete when there are no sessions at all", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const registryWithNotifier: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const allCompleteConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "all-complete": { + auto: true, + action: "notify", + priority: "action", + }, + }, + }; + + vi.mocked(mockSessionManager.list).mockResolvedValue([]); + + const lm = createLifecycleManager({ + config: allCompleteConfig, + registry: registryWithNotifier, + sessionManager: mockSessionManager, + }); + + lm.start(5000); + await vi.advanceTimersByTimeAsync(0); + + // sessions.length === 0, so all-complete should NOT fire + expect(mockNotifier.notify).not.toHaveBeenCalled(); + + lm.stop(); + }); +}); + +describe("reaction tracking and escalation", () => { + it("escalates after exceeding retry count (numeric escalateAfter)", async () => { + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const escalationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 1, // will escalate on attempt 2 + escalateAfter: 1, // numeric: escalate after 1 attempt + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: escalationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + // First check: pr_open → ci_failed (attempt 1) + await lm.check("app-1"); + + // Attempt 1 should send to agent, not escalate yet + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + expect(mockNotifier.notify).not.toHaveBeenCalled(); + + // Simulate: CI still failing, but we need a status transition to trigger reaction again. + // Reset state to pr_open, then back to ci_failed. + vi.mocked(mockSCM.getCISummary).mockResolvedValueOnce("passing"); + vi.mocked(mockSCM.getReviewDecision).mockResolvedValueOnce("none"); + await lm.check("app-1"); // ci_failed → pr_open + + vi.mocked(mockSCM.getCISummary).mockResolvedValue("failing"); + vi.mocked(mockSCM.getReviewDecision).mockResolvedValue("none"); + + // Note: the transition from ci_failed to pr_open clears the reaction tracker + // for the old "ci-failed" key (line 449-455 in source). So each ci_failed transition + // starts with a fresh tracker. With retries=1, the first attempt (attempt 1) + // doesn't exceed maxRetries, so it sends to agent. + // With numeric escalateAfter=1, attempt 1 doesn't exceed 1 either. + // Attempt 2 would exceed both, but the tracker resets on state change. + // This tests that the numeric escalateAfter path is exercised. + await lm.check("app-1"); // pr_open → ci_failed (new tracker, attempt 1) + + // With fresh tracker, attempt 1 <= retries(1) and attempt 1 <= escalateAfter(1), + // so it should still send to agent + expect(mockSessionManager.send).toHaveBeenCalledTimes(2); + }); + + it("escalates when retries exceeded (without state transition resetting tracker)", async () => { + // To test escalation properly, we need repeated reactions on the SAME transition + // without the tracker being cleared. This happens when the same event type + // keeps firing. However, the lifecycle manager only triggers reactions on + // state *transitions*. To get multiple triggers without reset, we'd need + // the session to remain in ci_failed and the reaction to fire again. + // + // Looking at the code: reactions only fire when oldStatus !== newStatus. + // So the tracker can only accumulate across separate transitions to the same state. + // But each transition from ci_failed to something else clears the tracker. + // + // This means: with retries=1 and the tracker resetting on each state change, + // we can never actually reach attempt > 1 for the same tracker key + // through the public API. The escalation is designed to work across + // persistent ci_failed states polled repeatedly — but pollAll only triggers + // reactions on transitions. + // + // However: if retries = 0, then attempt 1 > maxRetries(0), so it escalates immediately. + + const mockNotifier: Notifier = { + name: "mock-notifier", + notify: vi.fn().mockResolvedValue(undefined), + }; + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithAll: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string, name: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + if (slot === "notifier" && name === "desktop") return mockNotifier; + return null; + }), + }; + + const escalationConfig: OrchestratorConfig = { + ...config, + notificationRouting: { + urgent: ["desktop"], + action: ["desktop"], + warning: ["desktop"], + info: ["desktop"], + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 0, // escalate immediately on first attempt (1 > 0) + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: escalationConfig, + registry: registryWithAll, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("ci_failed"); + // With retries=0, attempt 1 > 0, so escalation fires immediately + expect(mockNotifier.notify).toHaveBeenCalledWith( + expect.objectContaining({ + type: "reaction.escalated", + priority: "urgent", // default escalation priority + }), + ); + // send-to-agent should NOT have been called (escalation path returns early) + expect(mockSessionManager.send).not.toHaveBeenCalled(); + }); + + it("clears reaction tracker when state transitions away from the triggering status", async () => { + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithSCM: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + return null; + }), + }; + + const reactionConfig: OrchestratorConfig = { + ...config, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 100, + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: reactionConfig, + registry: registryWithSCM, + sessionManager: mockSessionManager, + }); + + // First transition: pr_open → ci_failed + await lm.check("app-1"); + expect(mockSessionManager.send).toHaveBeenCalledTimes(1); + + // Transition away: ci_failed → pr_open (CI passes) + vi.mocked(mockSCM.getCISummary).mockResolvedValueOnce("passing"); + vi.mocked(mockSCM.getReviewDecision).mockResolvedValueOnce("none"); + await lm.check("app-1"); + expect(lm.getStates().get("app-1")).toBe("pr_open"); + + // Transition back: pr_open → ci_failed + vi.mocked(mockSCM.getCISummary).mockResolvedValue("failing"); + vi.mocked(mockSCM.getReviewDecision).mockResolvedValue("none"); + await lm.check("app-1"); + expect(lm.getStates().get("app-1")).toBe("ci_failed"); + + // The tracker should have been cleared when state changed from ci_failed, + // so this is treated as a fresh first attempt (not attempt 2) + expect(mockSessionManager.send).toHaveBeenCalledTimes(2); + expect(mockSessionManager.send).toHaveBeenLastCalledWith("app-1", "Fix CI"); + }); + + it("uses project-specific reaction overrides when configured", async () => { + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithSCM: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + return null; + }), + }; + + // Global reaction has one message, project override has another + const projectOverrideConfig: OrchestratorConfig = { + ...config, + projects: { + "my-app": { + ...config.projects["my-app"], + reactions: { + "ci-failed": { + message: "Project-specific: fix the CI please!", + }, + }, + }, + }, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Global: fix CI", + retries: 3, + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: projectOverrideConfig, + registry: registryWithSCM, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + + // Project-specific message should override global + expect(mockSessionManager.send).toHaveBeenCalledWith( + "app-1", + "Project-specific: fix the CI please!", + ); + }); + + it("handles send-to-agent failure gracefully (returns success=false)", async () => { + vi.mocked(mockSessionManager.send).mockRejectedValue(new Error("tmux send failed")); + + const mockSCM: SCM = { + name: "mock-scm", + detectPR: vi.fn(), + getPRState: vi.fn().mockResolvedValue("open"), + mergePR: vi.fn(), + closePR: vi.fn(), + getCIChecks: vi.fn(), + getCISummary: vi.fn().mockResolvedValue("failing"), + getReviews: vi.fn(), + getReviewDecision: vi.fn().mockResolvedValue("none"), + getPendingComments: vi.fn(), + getAutomatedComments: vi.fn(), + getMergeability: vi.fn(), + }; + + const registryWithSCM: PluginRegistry = { + ...mockRegistry, + get: vi.fn().mockImplementation((slot: string) => { + if (slot === "runtime") return mockRuntime; + if (slot === "agent") return mockAgent; + if (slot === "scm") return mockSCM; + return null; + }), + }; + + const reactionConfig: OrchestratorConfig = { + ...config, + reactions: { + "ci-failed": { + auto: true, + action: "send-to-agent", + message: "Fix CI", + retries: 3, + }, + }, + }; + + const session = makeSession({ status: "pr_open", pr: makePR() }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "pr_open", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config: reactionConfig, + registry: registryWithSCM, + sessionManager: mockSessionManager, + }); + + // Should not throw — the reaction catches the send error + await lm.check("app-1"); + + expect(lm.getStates().get("app-1")).toBe("ci_failed"); + expect(mockSessionManager.send).toHaveBeenCalledWith("app-1", "Fix CI"); + }); +}); + +describe("event logging", () => { + it("logs state transitions when eventLogger is provided", async () => { + const mockEventLogger = { + append: vi.fn(), + appendLine: vi.fn(), + close: vi.fn(), + }; + + const session = makeSession({ status: "spawning" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "spawning", + project: "my-app", + }); + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + eventLogger: mockEventLogger, + }); + + await lm.check("app-1"); + + expect(mockEventLogger.append).toHaveBeenCalledWith( + expect.objectContaining({ + level: "info", + source: "lifecycle", + sessionId: "app-1", + message: expect.stringContaining("spawning"), + }), + ); + expect(mockEventLogger.append).toHaveBeenCalledWith( + expect.objectContaining({ + message: expect.stringContaining("working"), + }), + ); + }); + + it("closes eventLogger on stop", () => { + const mockEventLogger = { + append: vi.fn(), + appendLine: vi.fn(), + close: vi.fn(), + }; + + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + eventLogger: mockEventLogger, + }); + + lm.stop(); + + expect(mockEventLogger.close).toHaveBeenCalled(); + }); + + it("does not log when eventLogger is not provided", async () => { + const session = makeSession({ status: "spawning" }); + vi.mocked(mockSessionManager.get).mockResolvedValue(session); + + writeMetadata(sessionsDir, "app-1", { + worktree: "/tmp", + branch: "main", + status: "spawning", + project: "my-app", + }); + + // No eventLogger passed — should not throw + const lm = createLifecycleManager({ + config, + registry: mockRegistry, + sessionManager: mockSessionManager, + }); + + await lm.check("app-1"); + expect(lm.getStates().get("app-1")).toBe("working"); + }); +}); diff --git a/packages/core/src/__tests__/paths.test.ts b/packages/core/src/__tests__/paths.test.ts index 95ae0bc18..66d80a20e 100644 --- a/packages/core/src/__tests__/paths.test.ts +++ b/packages/core/src/__tests__/paths.test.ts @@ -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 diff --git a/packages/core/src/__tests__/retrospective.test.ts b/packages/core/src/__tests__/retrospective.test.ts index 8ab6dbf99..4ba5adaf8 100644 --- a/packages/core/src/__tests__/retrospective.test.ts +++ b/packages/core/src/__tests__/retrospective.test.ts @@ -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 { + 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 { + 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 }; +} { + 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 | null; + archiveMetadata?: Record | null; + reportCard?: Partial; + 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([]); + }); +}); diff --git a/packages/core/src/__tests__/utils-perf.test.ts b/packages/core/src/__tests__/utils-perf.test.ts index 34d244e52..c62824ca1 100644 --- a/packages/core/src/__tests__/utils-perf.test.ts +++ b/packages/core/src/__tests__/utils-perf.test.ts @@ -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"); + }); +}); diff --git a/packages/core/src/dashboard-manager.ts b/packages/core/src/dashboard-manager.ts index 2e4fbabae..f5fe5cb36 100644 --- a/packages/core/src/dashboard-manager.ts +++ b/packages/core/src/dashboard-manager.ts @@ -159,8 +159,8 @@ export async function restartDashboard(opts: DashboardRestartOpts): Promise; + 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 | undefined, + cacheStats: data["cacheStats"] as ApiLogEntry["cacheStats"] | undefined, + }; + + if (opts?.route && !req.path.includes(opts.route)) continue; + results.push(req); + } + + return results; +} diff --git a/packages/web/src/__tests__/observability-routes.test.ts b/packages/web/src/__tests__/observability-routes.test.ts index a54bedad1..6ba87e1f9 100644 --- a/packages/web/src/__tests__/observability-routes.test.ts +++ b/packages/web/src/__tests__/observability-routes.test.ts @@ -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"); + }); }); diff --git a/packages/web/src/lib/__tests__/client-logger.test.ts b/packages/web/src/lib/__tests__/client-logger.test.ts new file mode 100644 index 000000000..ef0d0cbdf --- /dev/null +++ b/packages/web/src/lib/__tests__/client-logger.test.ts @@ -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; + readonly reason: unknown; + + constructor( + type: string, + init: { promise: Promise; 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; +let sendBeaconSpy: ReturnType; +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(); + }); +}); diff --git a/packages/web/src/lib/__tests__/request-logger.test.ts b/packages/web/src/lib/__tests__/request-logger.test.ts new file mode 100644 index 000000000..099d015b9 --- /dev/null +++ b/packages/web/src/lib/__tests__/request-logger.test.ts @@ -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 }), + }, + }; +} diff --git a/packages/web/src/lib/__tests__/with-timing.test.ts b/packages/web/src/lib/__tests__/with-timing.test.ts new file mode 100644 index 000000000..74e6e0612 --- /dev/null +++ b/packages/web/src/lib/__tests__/with-timing.test.ts @@ -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(); + }); +});