fix(FN-2351): structure startup AI session cleanup diagnostics
- Add normalizeErrorForLog helper and use it to emit consistent structured error fields - Replace string-interpolated rehydrate and cleanup logs with structured summary payloads including source, ttl, and totals - Emit structured warning/error diagnostics for settings fallback, initial/scheduled cleanup failures, and dev-server shutdown cleanup failures - Add server startup tests covering structured cleanup success, failure, and settings-fallback logging behavior
This commit is contained in:
@@ -93,6 +93,165 @@ async function REQUEST(
|
|||||||
return performRequest(app, method, path, body, headers);
|
return performRequest(app, method, path, body, headers);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
async function flushStartupCleanupTasks(): Promise<void> {
|
||||||
|
await Promise.resolve();
|
||||||
|
await Promise.resolve();
|
||||||
|
await Promise.resolve();
|
||||||
|
}
|
||||||
|
|
||||||
|
describe("createServer AI session startup cleanup diagnostics", () => {
|
||||||
|
const originalNodeEnv = process.env.NODE_ENV;
|
||||||
|
|
||||||
|
beforeEach(() => {
|
||||||
|
vi.useFakeTimers();
|
||||||
|
process.env.NODE_ENV = "development";
|
||||||
|
});
|
||||||
|
|
||||||
|
afterEach(() => {
|
||||||
|
process.env.NODE_ENV = originalNodeEnv;
|
||||||
|
vi.useRealTimers();
|
||||||
|
vi.restoreAllMocks();
|
||||||
|
});
|
||||||
|
|
||||||
|
function createRuntimeLoggerMock() {
|
||||||
|
const logger = {
|
||||||
|
scope: "server",
|
||||||
|
info: vi.fn(),
|
||||||
|
warn: vi.fn(),
|
||||||
|
error: vi.fn(),
|
||||||
|
child: vi.fn(),
|
||||||
|
};
|
||||||
|
logger.child.mockReturnValue(logger);
|
||||||
|
return logger;
|
||||||
|
}
|
||||||
|
|
||||||
|
function createAiSessionStoreMock(overrides: Record<string, unknown> = {}) {
|
||||||
|
return {
|
||||||
|
on: vi.fn(),
|
||||||
|
off: vi.fn(),
|
||||||
|
recoverStaleSessions: vi.fn(),
|
||||||
|
listRecoverable: vi.fn().mockReturnValue([]),
|
||||||
|
cleanupStaleSessions: vi.fn().mockReturnValue({
|
||||||
|
terminalDeleted: 0,
|
||||||
|
orphanedDeleted: 0,
|
||||||
|
totalDeleted: 0,
|
||||||
|
}),
|
||||||
|
stopScheduledCleanup: vi.fn(),
|
||||||
|
...overrides,
|
||||||
|
};
|
||||||
|
}
|
||||||
|
|
||||||
|
it("logs structured startup cleanup summary on success", async () => {
|
||||||
|
const runtimeLogger = createRuntimeLoggerMock();
|
||||||
|
const aiSessionStore = createAiSessionStoreMock({
|
||||||
|
cleanupStaleSessions: vi.fn().mockReturnValue({
|
||||||
|
terminalDeleted: 2,
|
||||||
|
orphanedDeleted: 1,
|
||||||
|
totalDeleted: 3,
|
||||||
|
}),
|
||||||
|
});
|
||||||
|
const store = createMockStore({
|
||||||
|
getSettings: vi.fn().mockResolvedValue({
|
||||||
|
aiSessionTtlMs: 700_000,
|
||||||
|
aiSessionCleanupIntervalMs: 120_000,
|
||||||
|
}),
|
||||||
|
});
|
||||||
|
|
||||||
|
createServer(store, {
|
||||||
|
runtimeLogger: runtimeLogger as any,
|
||||||
|
aiSessionStore: aiSessionStore as any,
|
||||||
|
headless: true,
|
||||||
|
});
|
||||||
|
|
||||||
|
await flushStartupCleanupTasks();
|
||||||
|
|
||||||
|
expect(aiSessionStore.cleanupStaleSessions).toHaveBeenCalledWith(700_000);
|
||||||
|
expect(runtimeLogger.info).toHaveBeenCalledWith(
|
||||||
|
"AI session cleanup summary",
|
||||||
|
expect.objectContaining({
|
||||||
|
message: "Removed stale AI sessions",
|
||||||
|
source: "initial",
|
||||||
|
ttlMs: 700_000,
|
||||||
|
terminalDeleted: 2,
|
||||||
|
orphanedDeleted: 1,
|
||||||
|
totalDeleted: 3,
|
||||||
|
}),
|
||||||
|
);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("logs structured startup cleanup failure and keeps server creation non-fatal", async () => {
|
||||||
|
const runtimeLogger = createRuntimeLoggerMock();
|
||||||
|
const aiSessionStore = createAiSessionStoreMock({
|
||||||
|
cleanupStaleSessions: vi.fn().mockImplementation(() => {
|
||||||
|
throw new Error("cleanup exploded");
|
||||||
|
}),
|
||||||
|
});
|
||||||
|
const store = createMockStore({
|
||||||
|
getSettings: vi.fn().mockResolvedValue({
|
||||||
|
aiSessionTtlMs: 900_000,
|
||||||
|
aiSessionCleanupIntervalMs: 180_000,
|
||||||
|
}),
|
||||||
|
});
|
||||||
|
|
||||||
|
const app = createServer(store, {
|
||||||
|
runtimeLogger: runtimeLogger as any,
|
||||||
|
aiSessionStore: aiSessionStore as any,
|
||||||
|
headless: true,
|
||||||
|
});
|
||||||
|
|
||||||
|
await flushStartupCleanupTasks();
|
||||||
|
|
||||||
|
expect(app).toBeDefined();
|
||||||
|
expect(runtimeLogger.error).toHaveBeenCalledWith(
|
||||||
|
"AI session cleanup failed",
|
||||||
|
expect.objectContaining({
|
||||||
|
message: "Initial AI session cleanup failed",
|
||||||
|
source: "initial",
|
||||||
|
ttlMs: 900_000,
|
||||||
|
errorName: "Error",
|
||||||
|
errorMessage: "cleanup exploded",
|
||||||
|
error: "cleanup exploded",
|
||||||
|
}),
|
||||||
|
);
|
||||||
|
});
|
||||||
|
|
||||||
|
it("logs structured settings fallback warning and continues with default cleanup values", async () => {
|
||||||
|
const runtimeLogger = createRuntimeLoggerMock();
|
||||||
|
const aiSessionStore = createAiSessionStoreMock({
|
||||||
|
cleanupStaleSessions: vi.fn().mockReturnValue({
|
||||||
|
terminalDeleted: 1,
|
||||||
|
orphanedDeleted: 0,
|
||||||
|
totalDeleted: 1,
|
||||||
|
}),
|
||||||
|
});
|
||||||
|
const store = createMockStore({
|
||||||
|
getSettings: vi.fn().mockRejectedValue(new Error("settings unavailable")),
|
||||||
|
});
|
||||||
|
|
||||||
|
const app = createServer(store, {
|
||||||
|
runtimeLogger: runtimeLogger as any,
|
||||||
|
aiSessionStore: aiSessionStore as any,
|
||||||
|
headless: true,
|
||||||
|
});
|
||||||
|
|
||||||
|
await flushStartupCleanupTasks();
|
||||||
|
|
||||||
|
expect(app).toBeDefined();
|
||||||
|
expect(runtimeLogger.warn).toHaveBeenCalledWith(
|
||||||
|
"AI session cleanup settings fallback",
|
||||||
|
expect.objectContaining({
|
||||||
|
message: "Failed to load settings for AI session cleanup; using defaults",
|
||||||
|
fallbackTtlMs: 7 * 24 * 60 * 60 * 1000,
|
||||||
|
fallbackCleanupIntervalMs: 6 * 60 * 60 * 1000,
|
||||||
|
errorName: "Error",
|
||||||
|
errorMessage: "settings unavailable",
|
||||||
|
error: "settings unavailable",
|
||||||
|
}),
|
||||||
|
);
|
||||||
|
expect(aiSessionStore.cleanupStaleSessions).toHaveBeenCalledWith(7 * 24 * 60 * 60 * 1000);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
|
||||||
describe("createServer health and headless mode", () => {
|
describe("createServer health and headless mode", () => {
|
||||||
it("returns liveness payload from /api/health", async () => {
|
it("returns liveness payload from /api/health", async () => {
|
||||||
const store = createMockStore();
|
const store = createMockStore();
|
||||||
|
|||||||
@@ -280,6 +280,28 @@ function shouldScheduleAiSessionCleanup(): boolean {
|
|||||||
return process.env.NODE_ENV !== "test";
|
return process.env.NODE_ENV !== "test";
|
||||||
}
|
}
|
||||||
|
|
||||||
|
function normalizeErrorForLog(err: unknown): {
|
||||||
|
error: string;
|
||||||
|
errorName?: string;
|
||||||
|
errorMessage: string;
|
||||||
|
errorStack?: string;
|
||||||
|
} {
|
||||||
|
if (err instanceof Error) {
|
||||||
|
return {
|
||||||
|
error: err.message,
|
||||||
|
errorName: err.name,
|
||||||
|
errorMessage: err.message,
|
||||||
|
errorStack: err.stack,
|
||||||
|
};
|
||||||
|
}
|
||||||
|
|
||||||
|
const fallback = String(err);
|
||||||
|
return {
|
||||||
|
error: fallback,
|
||||||
|
errorMessage: fallback,
|
||||||
|
};
|
||||||
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Resolve TLS credentials from environment variables, if configured.
|
* Resolve TLS credentials from environment variables, if configured.
|
||||||
*
|
*
|
||||||
@@ -681,9 +703,14 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
const totalRehydrated =
|
const totalRehydrated =
|
||||||
planningRehydratedCount + subtaskRehydratedCount + missionRehydratedCount + milestoneSliceRehydratedCount;
|
planningRehydratedCount + subtaskRehydratedCount + missionRehydratedCount + milestoneSliceRehydratedCount;
|
||||||
if (totalRehydrated > 0) {
|
if (totalRehydrated > 0) {
|
||||||
runtimeLogger.info(
|
runtimeLogger.info("AI session rehydrate summary", {
|
||||||
`Rehydrated ${planningRehydratedCount} planning, ${subtaskRehydratedCount} subtask, ${missionRehydratedCount} mission, ${milestoneSliceRehydratedCount} milestone/slice sessions from SQLite`,
|
message: "Rehydrated AI sessions from SQLite",
|
||||||
);
|
planningRehydratedCount,
|
||||||
|
subtaskRehydratedCount,
|
||||||
|
missionRehydratedCount,
|
||||||
|
milestoneSliceRehydratedCount,
|
||||||
|
totalRehydrated,
|
||||||
|
});
|
||||||
}
|
}
|
||||||
|
|
||||||
// Create AgentStore for chat prompt enrichment (initialized lazily by ChatManager)
|
// Create AgentStore for chat prompt enrichment (initialized lazily by ChatManager)
|
||||||
@@ -694,9 +721,14 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
|
|
||||||
const runAiSessionCleanup = (maxAgeMs: number, source: "initial" | "scheduled") => {
|
const runAiSessionCleanup = (maxAgeMs: number, source: "initial" | "scheduled") => {
|
||||||
const result = aiSessionStore.cleanupStaleSessions(maxAgeMs);
|
const result = aiSessionStore.cleanupStaleSessions(maxAgeMs);
|
||||||
runtimeLogger.info(
|
runtimeLogger.info("AI session cleanup summary", {
|
||||||
`AI session cleanup (${source}): removed ${result.terminalDeleted} terminal, ${result.orphanedDeleted} orphaned sessions`,
|
message: "Removed stale AI sessions",
|
||||||
);
|
source,
|
||||||
|
ttlMs: maxAgeMs,
|
||||||
|
terminalDeleted: result.terminalDeleted,
|
||||||
|
orphanedDeleted: result.orphanedDeleted,
|
||||||
|
totalDeleted: result.totalDeleted,
|
||||||
|
});
|
||||||
return result;
|
return result;
|
||||||
};
|
};
|
||||||
|
|
||||||
@@ -706,8 +738,12 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
try {
|
try {
|
||||||
runAiSessionCleanup(maxAgeMs, "scheduled");
|
runAiSessionCleanup(maxAgeMs, "scheduled");
|
||||||
} catch (err) {
|
} catch (err) {
|
||||||
runtimeLogger.error("Scheduled AI session cleanup failed", {
|
runtimeLogger.error("AI session cleanup failed", {
|
||||||
error: err instanceof Error ? err.message : String(err),
|
message: "Scheduled AI session cleanup failed",
|
||||||
|
source: "scheduled",
|
||||||
|
ttlMs: maxAgeMs,
|
||||||
|
cleanupIntervalMs,
|
||||||
|
...normalizeErrorForLog(err),
|
||||||
});
|
});
|
||||||
}
|
}
|
||||||
}, cleanupIntervalMs);
|
}, cleanupIntervalMs);
|
||||||
@@ -736,23 +772,32 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
void Promise.resolve()
|
void Promise.resolve()
|
||||||
.then(() => runAiSessionCleanup(ttlMs, "initial"))
|
.then(() => runAiSessionCleanup(ttlMs, "initial"))
|
||||||
.catch((err) => {
|
.catch((err) => {
|
||||||
runtimeLogger.error("Initial AI session cleanup failed", {
|
runtimeLogger.error("AI session cleanup failed", {
|
||||||
error: err instanceof Error ? err.message : String(err),
|
message: "Initial AI session cleanup failed",
|
||||||
|
source: "initial",
|
||||||
|
ttlMs,
|
||||||
|
...normalizeErrorForLog(err),
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
scheduleAiSessionCleanup(cleanupIntervalMs, ttlMs);
|
scheduleAiSessionCleanup(cleanupIntervalMs, ttlMs);
|
||||||
})
|
})
|
||||||
.catch((err) => {
|
.catch((err) => {
|
||||||
runtimeLogger.warn("Failed to load settings for AI session cleanup; using defaults", {
|
runtimeLogger.warn("AI session cleanup settings fallback", {
|
||||||
error: err instanceof Error ? err.message : String(err),
|
message: "Failed to load settings for AI session cleanup; using defaults",
|
||||||
|
fallbackTtlMs: DEFAULT_AI_SESSION_TTL_MS,
|
||||||
|
fallbackCleanupIntervalMs: DEFAULT_AI_SESSION_CLEANUP_INTERVAL_MS,
|
||||||
|
...normalizeErrorForLog(err),
|
||||||
});
|
});
|
||||||
|
|
||||||
void Promise.resolve()
|
void Promise.resolve()
|
||||||
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
|
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
|
||||||
.catch((cleanupErr) => {
|
.catch((cleanupErr) => {
|
||||||
runtimeLogger.error("Initial AI session cleanup failed", {
|
runtimeLogger.error("AI session cleanup failed", {
|
||||||
error: cleanupErr instanceof Error ? cleanupErr.message : String(cleanupErr),
|
message: "Initial AI session cleanup failed",
|
||||||
|
source: "initial",
|
||||||
|
ttlMs: DEFAULT_AI_SESSION_TTL_MS,
|
||||||
|
...normalizeErrorForLog(cleanupErr),
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
@@ -765,8 +810,11 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
void Promise.resolve()
|
void Promise.resolve()
|
||||||
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
|
.then(() => runAiSessionCleanup(DEFAULT_AI_SESSION_TTL_MS, "initial"))
|
||||||
.catch((err) => {
|
.catch((err) => {
|
||||||
runtimeLogger.error("Initial AI session cleanup failed", {
|
runtimeLogger.error("AI session cleanup failed", {
|
||||||
error: err instanceof Error ? err.message : String(err),
|
message: "Initial AI session cleanup failed",
|
||||||
|
source: "initial",
|
||||||
|
ttlMs: DEFAULT_AI_SESSION_TTL_MS,
|
||||||
|
...normalizeErrorForLog(err),
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
@@ -867,8 +915,10 @@ export function createServer(store: TaskStore, options?: ServerOptions): ReturnT
|
|||||||
clearAiSessionCleanupInterval();
|
clearAiSessionCleanupInterval();
|
||||||
aiSessionStore.stopScheduledCleanup();
|
aiSessionStore.stopScheduledCleanup();
|
||||||
void stopAllDevServers().catch((error) => {
|
void stopAllDevServers().catch((error) => {
|
||||||
const message = error instanceof Error ? error.message : String(error);
|
runtimeLogger.warn("Failed to shutdown dev-server managers", {
|
||||||
runtimeLogger.warn(`Failed to shutdown dev-server managers: ${message}`);
|
message: "Failed to shutdown dev-server managers",
|
||||||
|
...normalizeErrorForLog(error),
|
||||||
|
});
|
||||||
});
|
});
|
||||||
});
|
});
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user