|
| 1 | +import { describe, it, expect, beforeAll, afterAll, vi } from "vitest"; |
| 2 | +import { mkdtempSync, readFileSync, existsSync, writeFileSync } from "fs"; |
| 3 | +import { tmpdir } from "os"; |
| 4 | +import { join } from "path"; |
| 5 | +import { rmSync } from "fs"; |
| 6 | + |
| 7 | +let logDir; |
| 8 | +let logger; |
| 9 | + |
| 10 | +describe("logger — basic writes", () => { |
| 11 | + beforeAll(async () => { |
| 12 | + logDir = mkdtempSync(join(tmpdir(), "backlog-logger-test-")); |
| 13 | + vi.resetModules(); |
| 14 | + process.env.BACKLOG_LOG_DIR = logDir; |
| 15 | + process.env.LOG_LEVEL = "trace"; |
| 16 | + ({ logger } = await import("../logger.js")); |
| 17 | + }); |
| 18 | + |
| 19 | + afterAll(() => { |
| 20 | + delete process.env.BACKLOG_LOG_DIR; |
| 21 | + delete process.env.LOG_LEVEL; |
| 22 | + try { rmSync(logDir, { recursive: true, force: true }); } catch (_) {} |
| 23 | + }); |
| 24 | + |
| 25 | + it("logger.info writes a JSON line to the log file", () => { |
| 26 | + logger.info("test-info-message", { key: "value" }); |
| 27 | + const logFile = join(logDir, "agent-backlog.log"); |
| 28 | + expect(existsSync(logFile)).toBe(true); |
| 29 | + const content = readFileSync(logFile, "utf8"); |
| 30 | + expect(content).toContain("test-info-message"); |
| 31 | + expect(content).toContain('"level":"info"'); |
| 32 | + }); |
| 33 | + |
| 34 | + it("logger.warn writes a JSON line", () => { |
| 35 | + logger.warn("test-warn-message"); |
| 36 | + const content = readFileSync(join(logDir, "agent-backlog.log"), "utf8"); |
| 37 | + expect(content).toContain("test-warn-message"); |
| 38 | + }); |
| 39 | + |
| 40 | + it("logger.error writes a JSON line", () => { |
| 41 | + logger.error("test-error-message"); |
| 42 | + const content = readFileSync(join(logDir, "agent-backlog.log"), "utf8"); |
| 43 | + expect(content).toContain("test-error-message"); |
| 44 | + }); |
| 45 | + |
| 46 | + it("logger.debug writes a JSON line (level=trace allows it)", () => { |
| 47 | + logger.debug("test-debug-message"); |
| 48 | + const content = readFileSync(join(logDir, "agent-backlog.log"), "utf8"); |
| 49 | + expect(content).toContain("test-debug-message"); |
| 50 | + }); |
| 51 | + |
| 52 | + it("logger.trace writes a JSON line (level=trace allows it)", () => { |
| 53 | + logger.trace("test-trace-message"); |
| 54 | + const content = readFileSync(join(logDir, "agent-backlog.log"), "utf8"); |
| 55 | + expect(content).toContain("test-trace-message"); |
| 56 | + }); |
| 57 | +}); |
| 58 | + |
| 59 | +describe("logger — inode detection (checkInode)", () => { |
| 60 | + it("reopens log file when inode changes (external rotation simulation)", async () => { |
| 61 | + const inodeDir = mkdtempSync(join(tmpdir(), "backlog-logger-inode-")); |
| 62 | + vi.resetModules(); |
| 63 | + process.env.BACKLOG_LOG_DIR = inodeDir; |
| 64 | + process.env.LOG_LEVEL = "info"; |
| 65 | + |
| 66 | + const { logger: inodeLogger } = await import("../logger.js"); |
| 67 | + |
| 68 | + const logFile = join(inodeDir, "agent-backlog.log"); |
| 69 | + inodeLogger.info("before-rotation"); |
| 70 | + expect(existsSync(logFile)).toBe(true); |
| 71 | + |
| 72 | + // Simulate external rotation: rename the current log file |
| 73 | + const { renameSync } = await import("fs"); |
| 74 | + renameSync(logFile, `${logFile}.old`); |
| 75 | + |
| 76 | + // Next write should detect inode mismatch and reopen (creates new file) |
| 77 | + inodeLogger.info("after-rotation"); |
| 78 | + expect(existsSync(logFile)).toBe(true); |
| 79 | + |
| 80 | + delete process.env.BACKLOG_LOG_DIR; |
| 81 | + delete process.env.LOG_LEVEL; |
| 82 | + try { rmSync(inodeDir, { recursive: true, force: true }); } catch (_) {} |
| 83 | + }); |
| 84 | +}); |
| 85 | + |
| 86 | +describe("logger — rotation (rotate)", () => { |
| 87 | + it("rotates log file when it exceeds LOG_MAX_FILE_BYTES", async () => { |
| 88 | + const rotDir = mkdtempSync(join(tmpdir(), "backlog-logger-rotate-")); |
| 89 | + vi.resetModules(); |
| 90 | + process.env.BACKLOG_LOG_DIR = rotDir; |
| 91 | + process.env.LOG_LEVEL = "info"; |
| 92 | + |
| 93 | + // Mock config to set a 1-byte max so rotation triggers immediately |
| 94 | + vi.doMock("../config/config.js", async (importOriginal) => { |
| 95 | + const real = await importOriginal(); |
| 96 | + return { ...real, LOG_MAX_FILE_BYTES: 1 }; |
| 97 | + }); |
| 98 | + |
| 99 | + const { logger: rotLogger } = await import("../logger.js"); |
| 100 | + const logFile = join(rotDir, "agent-backlog.log"); |
| 101 | + |
| 102 | + rotLogger.info("first-write-opens-file"); |
| 103 | + expect(existsSync(logFile)).toBe(true); |
| 104 | + |
| 105 | + // Second write: file is now >= 1 byte, so rotation triggers |
| 106 | + rotLogger.info("second-write-triggers-rotation"); |
| 107 | + |
| 108 | + expect(existsSync(`${logFile}.1`)).toBe(true); |
| 109 | + |
| 110 | + delete process.env.BACKLOG_LOG_DIR; |
| 111 | + delete process.env.LOG_LEVEL; |
| 112 | + vi.restoreAllMocks(); |
| 113 | + try { rmSync(rotDir, { recursive: true, force: true }); } catch (_) {} |
| 114 | + }); |
| 115 | +}); |
| 116 | + |
| 117 | +describe("logger — checkInode fstatSync error (outer catch)", () => { |
| 118 | + it("handles fstatSync throwing in checkInode", async () => { |
| 119 | + const catchDir = mkdtempSync(join(tmpdir(), "backlog-logger-catch-")); |
| 120 | + vi.resetModules(); |
| 121 | + process.env.BACKLOG_LOG_DIR = catchDir; |
| 122 | + process.env.LOG_LEVEL = "info"; |
| 123 | + |
| 124 | + let fstatCallCount = 0; |
| 125 | + vi.doMock("fs", async (importOriginal) => { |
| 126 | + const real = await importOriginal(); |
| 127 | + return { |
| 128 | + ...real, |
| 129 | + fstatSync: (...args) => { |
| 130 | + fstatCallCount++; |
| 131 | + // write() calls checkInode then rotate, each calls fstatSync once. |
| 132 | + // First write: checkInode=call1, rotate=call2 |
| 133 | + // Second write: checkInode=call3 <- throw here to hit outer catch |
| 134 | + if (fstatCallCount === 3) throw new Error("mock-fstat-failure"); |
| 135 | + return real.fstatSync(...args); |
| 136 | + }, |
| 137 | + }; |
| 138 | + }); |
| 139 | + |
| 140 | + const { logger: catchLogger } = await import("../logger.js"); |
| 141 | + const stderrSpy = vi.spyOn(console, "error").mockImplementation(() => {}); |
| 142 | + |
| 143 | + catchLogger.info("first-opens-file"); |
| 144 | + // second write: checkInode's fstatSync will throw, triggering outer catch |
| 145 | + catchLogger.info("second-triggers-inode-check"); |
| 146 | + |
| 147 | + expect(stderrSpy).toHaveBeenCalledWith("logger:inode-check-error", "mock-fstat-failure"); |
| 148 | + |
| 149 | + stderrSpy.mockRestore(); |
| 150 | + delete process.env.BACKLOG_LOG_DIR; |
| 151 | + delete process.env.LOG_LEVEL; |
| 152 | + vi.restoreAllMocks(); |
| 153 | + try { rmSync(catchDir, { recursive: true, force: true }); } catch (_) {} |
| 154 | + }); |
| 155 | +}); |
| 156 | + |
| 157 | +describe("logger — rotate fstatSync error (rotate catch)", () => { |
| 158 | + it("handles fstatSync throwing in rotate", async () => { |
| 159 | + const rotCatchDir = mkdtempSync(join(tmpdir(), "backlog-logger-rotcatch-")); |
| 160 | + vi.resetModules(); |
| 161 | + process.env.BACKLOG_LOG_DIR = rotCatchDir; |
| 162 | + process.env.LOG_LEVEL = "info"; |
| 163 | + |
| 164 | + let fstatCallCount = 0; |
| 165 | + vi.doMock("fs", async (importOriginal) => { |
| 166 | + const real = await importOriginal(); |
| 167 | + return { |
| 168 | + ...real, |
| 169 | + fstatSync: (...args) => { |
| 170 | + fstatCallCount++; |
| 171 | + // write() calls checkInode then rotate, each calls fstatSync once. |
| 172 | + // First write: checkInode=call1, rotate=call2 |
| 173 | + // Second write: checkInode=call3, rotate=call4 <- throw here |
| 174 | + if (fstatCallCount === 4) throw new Error("mock-rotate-fstat-failure"); |
| 175 | + return real.fstatSync(...args); |
| 176 | + }, |
| 177 | + }; |
| 178 | + }); |
| 179 | + |
| 180 | + const { logger: rotCatchLogger } = await import("../logger.js"); |
| 181 | + const stderrSpy = vi.spyOn(console, "error").mockImplementation(() => {}); |
| 182 | + |
| 183 | + rotCatchLogger.info("first-opens-file"); |
| 184 | + // second write triggers rotate, which calls fstatSync and throws |
| 185 | + rotCatchLogger.info("second-triggers-rotate-error"); |
| 186 | + |
| 187 | + expect(stderrSpy).toHaveBeenCalledWith("logger:fstat-error", "mock-rotate-fstat-failure"); |
| 188 | + |
| 189 | + stderrSpy.mockRestore(); |
| 190 | + delete process.env.BACKLOG_LOG_DIR; |
| 191 | + delete process.env.LOG_LEVEL; |
| 192 | + vi.restoreAllMocks(); |
| 193 | + try { rmSync(rotCatchDir, { recursive: true, force: true }); } catch (_) {} |
| 194 | + }); |
| 195 | +}); |
| 196 | + |
| 197 | +describe("logger — write error catch", () => { |
| 198 | + it("logs to stderr instead of throwing when writeSync fails", async () => { |
| 199 | + const errDir = mkdtempSync(join(tmpdir(), "backlog-logger-err-")); |
| 200 | + vi.resetModules(); |
| 201 | + process.env.BACKLOG_LOG_DIR = errDir; |
| 202 | + process.env.LOG_LEVEL = "info"; |
| 203 | + |
| 204 | + // Mock fs to make writeSync throw |
| 205 | + vi.doMock("fs", async (importOriginal) => { |
| 206 | + const real = await importOriginal(); |
| 207 | + return { |
| 208 | + ...real, |
| 209 | + writeSync: () => { throw new Error("mock-write-failure"); }, |
| 210 | + }; |
| 211 | + }); |
| 212 | + |
| 213 | + const { logger: errLogger } = await import("../logger.js"); |
| 214 | + const stderrSpy = vi.spyOn(console, "error").mockImplementation(() => {}); |
| 215 | + |
| 216 | + // Should not throw; error is caught and logged to stderr |
| 217 | + expect(() => errLogger.info("write-will-fail")).not.toThrow(); |
| 218 | + expect(stderrSpy).toHaveBeenCalledWith("logger:write-error", "mock-write-failure"); |
| 219 | + |
| 220 | + stderrSpy.mockRestore(); |
| 221 | + delete process.env.BACKLOG_LOG_DIR; |
| 222 | + delete process.env.LOG_LEVEL; |
| 223 | + vi.restoreAllMocks(); |
| 224 | + try { rmSync(errDir, { recursive: true, force: true }); } catch (_) {} |
| 225 | + }); |
| 226 | +}); |
0 commit comments