import { beforeEach, describe, expect, it, vi } from "vitest"; import { encodedBytes, _resetForTesting, MAX_ENTRY_BYTES, type LogEntry } from "./buffer"; import { beginBrowserLogCapture, _resetRuntimeForTesting, browserLogMetadata, snapshotBrowserLogs, stageLogEntry, } from "./runtime"; const storeMocks = vi.hoisted(() => ({ append: vi.fn(), beginCaptureBoundary: vi.fn(), readPage: vi.fn(), })); const TEST_SOURCE = "test"; const TEST_SCOPE = "default-user"; const RECEIPT_MESSAGE = "receipt-entry"; vi.mock("./indexeddb-store", () => ({ IndexedDBLogStore: class { append = storeMocks.append; beginCaptureBoundary = storeMocks.beginCaptureBoundary; readPage = storeMocks.readPage; }, })); beforeEach(() => { _resetForTesting(); _resetRuntimeForTesting(); storeMocks.append.mockReset(); storeMocks.beginCaptureBoundary.mockReset().mockResolvedValue(0); storeMocks.readPage.mockReset().mockResolvedValue({ entries: [], nextCursor: null, done: true, }); }); describe("browser logger scheduling", () => { it("keeps the collection window before scheduling browser-idle persistence", async () => { vi.useFakeTimers(); let idleCallback: (() => void) | undefined; const requestIdle = vi.fn((callback: () => void, options: { timeout: number }) => { idleCallback = callback; return options.timeout; }); const cancelIdle = vi.fn(); vi.stubGlobal("requestIdleCallback", requestIdle); vi.stubGlobal("cancelIdleCallback", cancelIdle); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "idle-after-window", }); await vi.advanceTimersByTimeAsync(249); expect(requestIdle).not.toHaveBeenCalled(); expect(storeMocks.append).not.toHaveBeenCalled(); await vi.advanceTimersByTimeAsync(1); expect(requestIdle).toHaveBeenCalledTimes(1); expect(requestIdle.mock.calls[0]?.[1]).toEqual({ timeout: 750 }); expect(storeMocks.append).not.toHaveBeenCalled(); idleCallback?.(); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(1)); } finally { vi.unstubAllGlobals(); vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); it("uses the bounded deadline when browser idle time does not arrive", async () => { vi.useFakeTimers(); const requestIdle = vi.fn(() => 7); const cancelIdle = vi.fn(); vi.stubGlobal("requestIdleCallback", requestIdle); vi.stubGlobal("cancelIdleCallback", cancelIdle); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "idle-deadline", }); await vi.advanceTimersByTimeAsync(250); expect(storeMocks.append).not.toHaveBeenCalled(); await vi.advanceTimersByTimeAsync(749); expect(storeMocks.append).not.toHaveBeenCalled(); await vi.advanceTimersByTimeAsync(1); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(1)); expect(cancelIdle).toHaveBeenCalledWith(7); } finally { vi.unstubAllGlobals(); vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); it("bypasses a pending browser-idle wait when snapshotting", async () => { vi.useFakeTimers(); let idleCallback: (() => void) | undefined; const requestIdle = vi.fn((callback: () => void) => { idleCallback = callback; return 7; }); const cancelIdle = vi.fn(); vi.stubGlobal("requestIdleCallback", requestIdle); vi.stubGlobal("cancelIdleCallback", cancelIdle); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "snapshot-idle-bypass", }); await vi.advanceTimersByTimeAsync(250); expect(requestIdle).toHaveBeenCalledTimes(1); expect(storeMocks.append).not.toHaveBeenCalled(); await snapshotBrowserLogs(TEST_SCOPE); expect(storeMocks.append).toHaveBeenCalledTimes(1); expect(cancelIdle).toHaveBeenCalledWith(7); idleCallback?.(); await vi.advanceTimersByTimeAsync(750); expect(storeMocks.append).toHaveBeenCalledTimes(1); } finally { vi.unstubAllGlobals(); vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); }); describe("browser logger collection", () => { it("coalesces a log burst in one 250 ms window before one bounded append", async () => { vi.useFakeTimers(); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "first", }); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "second", }); expect(storeMocks.append).not.toHaveBeenCalled(); await vi.advanceTimersByTimeAsync(249); expect(storeMocks.append).not.toHaveBeenCalled(); await vi.advanceTimersByTimeAsync(1); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(1)); expect(storeMocks.append).toHaveBeenCalledWith( expect.arrayContaining([ expect.objectContaining({ entry: expect.objectContaining({ message: "first" }) }), expect.objectContaining({ entry: expect.objectContaining({ message: "second" }) }), ]), ); } finally { vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); it("passes one prepared entry and canonical byte count to persistence", async () => { vi.useFakeTimers(); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "prepared once", args: [{ detail: "value" }], }); await vi.advanceTimersByTimeAsync(250); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(1)); const batch = storeMocks.append.mock.calls[0]?.[0]; expect(batch).toEqual([ expect.objectContaining({ entry: expect.objectContaining({ message: "prepared once" }), bytes: expect.any(Number), }), ]); expect(batch[0].bytes).toBe(encodedBytes(batch[0].entry)); } finally { vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); }); describe("browser logger runtime", () => { it("flushes a pending collection window before snapshotting", async () => { vi.useFakeTimers(); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "flush before snapshot", }); await vi.advanceTimersByTimeAsync(100); expect(storeMocks.append).not.toHaveBeenCalled(); await snapshotBrowserLogs(TEST_SCOPE); expect(storeMocks.append).toHaveBeenCalledTimes(1); await vi.advanceTimersByTimeAsync(150); expect(storeMocks.append).toHaveBeenCalledTimes(1); } finally { vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); it("does not stage entries rejected by the bounded memory buffer", async () => { stageLogEntry({ timestamp: new Date().toISOString(), level: "error", source: "window.error", message: "x".repeat(MAX_ENTRY_BYTES + 1), }); await snapshotBrowserLogs(TEST_SCOPE); expect(storeMocks.append).not.toHaveBeenCalled(); }); it("falls back to memory when a persistence drain is rejected", async () => { storeMocks.append.mockRejectedValueOnce(new Error("IndexedDB upgrade blocked")); stageLogEntry({ timestamp: new Date().toISOString(), level: "error", source: TEST_SOURCE, message: "kept in memory", }); await expect(snapshotBrowserLogs(TEST_SCOPE)).resolves.toHaveLength(1); expect(browserLogMetadata()).toMatchObject({ storage_mode: "memory", persistence_failures: 1, }); }); it("serializes runtime drains and makes snapshots join the in-flight drain", async () => { vi.useFakeTimers(); let activeAppends = 0; let maximumActiveAppends = 0; let appendCalls = 0; let releaseFirstAppend: (() => void) | undefined; const firstAppend = new Promise((resolve) => { releaseFirstAppend = resolve; }); storeMocks.append.mockImplementation(async () => { appendCalls += 1; activeAppends += 1; maximumActiveAppends = Math.max(maximumActiveAppends, activeAppends); if (appendCalls === 1) await firstAppend; activeAppends -= 1; }); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "first", }); const snapshot = snapshotBrowserLogs(TEST_SCOPE); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(1)); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "second", }); vi.runOnlyPendingTimers(); await Promise.resolve(); expect(storeMocks.append).toHaveBeenCalledTimes(1); releaseFirstAppend?.(); await snapshot; await vi.advanceTimersByTimeAsync(250); await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(2)); expect(maximumActiveAppends).toBe(1); } finally { vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); }); describe("browser logger capture", () => { it("establishes the receipt boundary before flushing the receipt prefix", async () => { const order: string[] = []; storeMocks.beginCaptureBoundary.mockImplementation(async () => { order.push("boundary"); return 17; }); storeMocks.append.mockImplementation(async () => { order.push("append"); return [18]; }); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: RECEIPT_MESSAGE, }); const capture = await beginBrowserLogCapture(TEST_SCOPE); await capture.readPage?.(256, null); expect(storeMocks.beginCaptureBoundary).toHaveBeenCalledTimes(1); expect(order).toEqual(["boundary", "append"]); expect(storeMocks.readPage).toHaveBeenCalledWith(TEST_SCOPE, 256, null, 17, new Set([18])); }); it("keeps the persisted capture boundary fixed for every page", async () => { storeMocks.beginCaptureBoundary.mockResolvedValue(17); const capture = await beginBrowserLogCapture(TEST_SCOPE); await capture.readPage?.(256, null); expect(storeMocks.beginCaptureBoundary).toHaveBeenCalledTimes(1); expect(storeMocks.readPage).toHaveBeenCalledWith(TEST_SCOPE, 256, null, 17, new Set()); }); it("uses the receipt memory snapshot when the boundary cannot be proven", async () => { storeMocks.beginCaptureBoundary.mockRejectedValueOnce(new Error("boundary unavailable")); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: RECEIPT_MESSAGE, }); const capture = await beginBrowserLogCapture(TEST_SCOPE); expect(capture.storageMode).toBe("memory"); expect(capture.flushTimeout).toBe(false); expect(capture.memoryEntries.map(({ entry }) => entry.message)).toEqual([RECEIPT_MESSAGE]); expect(browserLogMetadata()).toMatchObject({ storage_mode: "indexeddb" }); }); }); describe("browser logger capture flush", () => { it("keeps a capture flush at the receipt watermark", async () => { vi.useFakeTimers(); let releaseFirstAppend: (() => void) | undefined; const firstAppend = new Promise((resolve) => { releaseFirstAppend = resolve; }); let appendCalls = 0; storeMocks.append.mockImplementation(async () => { appendCalls += 1; if (appendCalls === 1) await firstAppend; }); try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "at-receipt", }); const snapshot = snapshotBrowserLogs(TEST_SCOPE); await Promise.resolve(); expect(storeMocks.append).toHaveBeenCalledTimes(1); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "after-receipt", }); releaseFirstAppend?.(); await snapshot; expect(storeMocks.append).toHaveBeenCalledTimes(1); expect(storeMocks.append.mock.calls[0]?.[0]).toEqual([ expect.objectContaining({ entry: expect.objectContaining({ message: "at-receipt" }), }), ]); } finally { releaseFirstAppend?.(); vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); it("uses the receipt memory snapshot after the one-second flush timeout", async () => { vi.useFakeTimers(); let releaseFirstAppend: (() => void) | undefined; const firstAppend = new Promise((resolve) => { releaseFirstAppend = resolve; }); storeMocks.append.mockImplementation(() => firstAppend); let result: LogEntry[] | undefined; try { stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: RECEIPT_MESSAGE, }); const snapshot = snapshotBrowserLogs(TEST_SCOPE).then((entries) => { result = entries; }); await Promise.resolve(); expect(storeMocks.append).toHaveBeenCalledTimes(1); stageLogEntry({ timestamp: new Date().toISOString(), level: "info", source: TEST_SOURCE, message: "later-entry", }); await vi.advanceTimersByTimeAsync(999); expect(result).toBeUndefined(); await vi.advanceTimersByTimeAsync(1); await Promise.resolve(); expect(result?.map((entry) => entry.message)).toEqual([RECEIPT_MESSAGE]); expect(browserLogMetadata()).toMatchObject({ storage_mode: "indexeddb" }); releaseFirstAppend?.(); await snapshot; await vi.waitFor(() => expect(storeMocks.append).toHaveBeenCalledTimes(2)); } finally { releaseFirstAppend?.(); vi.runOnlyPendingTimers(); vi.useRealTimers(); } }); });