diff --git a/server/CLAUDE.md b/server/CLAUDE.md index 8f8d2f091..21ed6f041 100644 --- a/server/CLAUDE.md +++ b/server/CLAUDE.md @@ -94,6 +94,7 @@ SQLite is the engine today and Postgres is the planned second one. Code under `s - **`src/nest/common/`**: the global exception filter (error envelope), the Zod validation pipe, the idempotency interceptor (`X-Idempotency-Key` replay), and `validate-route-guards.ts` (boot-time ratchet refusing any public route not on its allow-list). - **Auth is default-deny**: the global auth guard and the MFA policy guard run as `APP_GUARD`s, followed by the managed-install guard (`managed.guard.ts`), which refuses the routes a centrally administered install withholds from its own admin — it runs last so strangers still get a 401, never a route-revealing 403. Routes opt out with `@Public()`/`@OptionalAuth()`. The global guard stands down for routes declaring their own guard chain, so `@UseGuards(JwtAuthGuard, TripAccessGuard)` + `@RequirePermission` stacks work. Session is a cookie (`trek_session`); `@CurrentUser()` reads the user. **Never gate a multipart upload with a guard** — guards run before the parser and the client sees ECONNRESET instead of your 403; check in the handler. +- **Logging**: `src/nest/audit/audit-log.logger.ts` (`logInfo`/`logWarn`/`logError`/`logDebug`) prints each line to the console and queues it for `data/logs/trek.log`, which `log-file.ts` appends in batches off the event loop and rotates at 10 MB over five files; `index.ts` flushes what is queued on exit. Never write the log file synchronously from a request path. - **`src/middleware/globalMiddleware.ts`** is the only Express middleware left (helmet/CSP, CORS, HSTS, forced-HTTPS, logging, cookies). ## Tests diff --git a/server/src/index.ts b/server/src/index.ts index 738ade58f..4679945f1 100644 --- a/server/src/index.ts +++ b/server/src/index.ts @@ -18,6 +18,7 @@ import type { DatabaseLifecycle } from './nest/database/database-lifecycle.servi import { getAppUrl, getMcpSafeUrl, readEnv } from './app-config'; import { resolveDataPaths } from './app-config/data-paths'; import { resolveDbPath } from './db/db-path'; +import { flushLogFileSync } from './nest/audit/audit-log.logger'; // data/tmp is the driver-agnostic global scratch dir (restore-upload spool, // mirror stream staging) and stays boot-created here. Driver-owned roots — the @@ -206,5 +207,10 @@ function shutdown(signal: string): void { }); } +// trek.log is written in batches off the event loop. Whatever is still queued +// when the process ends, by any of the exits above or below, goes out +// synchronously here: an 'exit' listener cannot wait for a promise. +process.on('exit', () => flushLogFileSync()); + process.on('SIGTERM', () => shutdown('SIGTERM')); process.on('SIGINT', () => shutdown('SIGINT')); diff --git a/server/src/nest/audit/audit-log.logger.ts b/server/src/nest/audit/audit-log.logger.ts index 0211f3b0b..899828185 100644 --- a/server/src/nest/audit/audit-log.logger.ts +++ b/server/src/nest/audit/audit-log.logger.ts @@ -1,14 +1,15 @@ import { readEnv } from '../../app-config'; import { resolveDataPaths } from '../../app-config/data-paths'; -import fs from 'fs'; -import path from 'path'; +import { BufferedLogFile } from './log-file'; /** - * The server's rotating file logger — a plain module, NOT an injectable - * (index.ts lazy-requires it before any Nest container exists). Directory - * creation is lazy (first write), so importing the module has no disk side - * effect; the LOG_LEVEL freeze below is the one deliberate import-time - * behavior and is load-bearing for tests/setup.ts. + * The server's rotating file logger, a plain module and NOT an injectable + * (index.ts lazy-requires it before any Nest container exists). Every line goes + * to the console at once and to `data/logs/trek.log` through a buffered, + * asynchronous sink (log-file.ts), so logging never waits for the disk. + * Nothing touches the disk at import: the directory appears with the first + * flush. The LOG_LEVEL freeze below is the one deliberate import-time behavior + * and is load-bearing for tests/setup.ts. */ // Frozen at import on purpose (legacy timing; tests/setup.ts sets it pre-import). @@ -29,48 +30,26 @@ const C = { reset: '\x1b[0m', }; -// ── File logger with rotation ───────────────────────────────────────────── +// ── File sink ───────────────────────────────────────────────────────────── -// From the data layout, like every other data path. It used to be cwd-based, -// which agreed only because the image and `npm run dev` both start in server/. -const logsDir = resolveDataPaths().logsDir; -const logFilePath = path.join(logsDir, 'trek.log'); -let logsDirReady = false; +const logFile = new BufferedLogFile({ + // From the data layout, like every other data path. It used to be cwd-based, + // which agreed only because the image and `npm run dev` both start in server/. + dir: resolveDataPaths().logsDir, + file: 'trek.log', + maxBytes: MAX_LOG_SIZE, + maxFiles: MAX_LOG_FILES, + onError: (message) => console.error(`[logger] ${message}`), +}); -function ensureLogsDir(): void { - if (logsDirReady) return; - try { - fs.mkdirSync(logsDir, { recursive: true }); - logsDirReady = true; - } catch (e) { - console.error(`[logger] could not create ${logsDir}: ${e instanceof Error ? e.message : e}`); - } +/** Resolves once every line logged so far is in trek.log. */ +export function flushLogFile(): Promise { + return logFile.flush(); } -function rotateIfNeeded(): void { - try { - if (!fs.existsSync(logFilePath)) return; - const stat = fs.statSync(logFilePath); - if (stat.size < MAX_LOG_SIZE) return; - - for (let i = MAX_LOG_FILES - 1; i >= 1; i--) { - const src = i === 1 ? logFilePath : `${logFilePath}.${i - 1}`; - const dst = `${logFilePath}.${i}`; - if (fs.existsSync(src)) fs.renameSync(src, dst); - } - } catch (e) { - console.error(`[logger] log rotation failed: ${e instanceof Error ? e.message : e}`); - } -} - -function writeToFile(line: string): void { - try { - ensureLogsDir(); - rotateIfNeeded(); - fs.appendFileSync(logFilePath, line + '\n'); - } catch (e) { - console.error(`[logger] log file write failed: ${e instanceof Error ? e.message : e}`); - } +/** Writes what is still queued, synchronously: for the process exit handler only. */ +export function flushLogFileSync(): void { + logFile.flushSync(); } // ── Public log helpers ──────────────────────────────────────────────────── @@ -84,27 +63,27 @@ export function logInfo(msg: string): void { if (LOG_THRESHOLD < LEVEL_RANKS.info) return; const ts = formatTs(); console.log(`${C.blue}[INFO]${C.reset} ${ts} ${msg}`); - writeToFile(`[INFO] ${ts} ${msg}`); + logFile.write(`[INFO] ${ts} ${msg}`); } export function logDebug(msg: string): void { if (LOG_THRESHOLD < LEVEL_RANKS.debug) return; const ts = formatTs(); console.log(`${C.cyan}[DEBUG]${C.reset} ${ts} ${msg}`); - writeToFile(`[DEBUG] ${ts} ${msg}`); + logFile.write(`[DEBUG] ${ts} ${msg}`); } export function logError(msg: string): void { const ts = formatTs(); console.error(`${C.red}[ERROR]${C.reset} ${ts} ${msg}`); - writeToFile(`[ERROR] ${ts} ${msg}`); + logFile.write(`[ERROR] ${ts} ${msg}`); } export function logWarn(msg: string): void { if (LOG_THRESHOLD < LEVEL_RANKS.warn) return; const ts = formatTs(); console.warn(`${C.yellow}[WARN]${C.reset} ${ts} ${msg}`); - writeToFile(`[WARN] ${ts} ${msg}`); + logFile.write(`[WARN] ${ts} ${msg}`); } export { LOG_LEVEL }; diff --git a/server/src/nest/audit/log-file.ts b/server/src/nest/audit/log-file.ts new file mode 100644 index 000000000..d9189b724 --- /dev/null +++ b/server/src/nest/audit/log-file.ts @@ -0,0 +1,209 @@ +import fs from 'node:fs'; +import path from 'node:path'; + +export interface LogFileOptions { + /** Directory the log lives in; created on the first write, never at construction. */ + dir: string; + /** File name inside `dir`. */ + file?: string; + /** Size at which the file is rotated to `.1`. */ + maxBytes?: number; + /** How many files exist at most, the live one included (``, `.1` ... `.`). */ + maxFiles?: number; + /** + * Ceiling on what may wait in memory while the disk is slow. Lines past it + * are counted and dropped, and the count is written once there is room + * again, so a stalled volume costs log lines rather than the process. + */ + maxBufferedBytes?: number; + /** How long a line may wait for others to share its write. */ + flushDelayMs?: number; + /** Where the sink reports its own failures; it never throws into a caller. */ + onError: (message: string) => void; +} + +const DEFAULTS = { + file: 'trek.log', + maxBytes: 10 * 1024 * 1024, + maxFiles: 5, + maxBufferedBytes: 4 * 1024 * 1024, + flushDelayMs: 50, +}; + +function errorMessage(err: unknown): string { + return err instanceof Error ? err.message : String(err); +} + +function isMissing(err: unknown): boolean { + return (err as NodeJS.ErrnoException | null)?.code === 'ENOENT'; +} + +/** + * The file half of the server log: lines are queued in memory and appended in + * batches, off the event loop, by one write at a time. + * + * The previous logger did `existsSync` + `statSync` + `appendFileSync` for + * every line, on the event loop, which a slow volume (an SMB or NFS bind + * mount) turned into a stall of every request. Here a line costs an array + * push; the disk sees one `appendFile` per batch. + * + * Rotation keeps its old shape (`trek.log` moves to `trek.log.1`, the oldest + * of `maxFiles` falls off) and is made safe in two ways. It runs inside the + * same serial chain as the writes, so no batch is appended while files are + * being renamed. And before rotating it re-reads the size on disk: when + * another process sharing the directory rotated first, the file is small + * again and this one only adopts the new size instead of rotating a second + * time and pushing a fresh file out. + */ +export class BufferedLogFile { + private readonly filePath: string; + private readonly opts: Required> & Pick; + private pending: string[] = []; + private pendingBytes = 0; + /** The batch whose append has not resolved yet; flushSync() writes it too, so an exit does not lose it. */ + private inFlight: string | null = null; + private dropped = 0; + /** Bytes in the live file as far as this process knows; read from disk before the first append. */ + private size: number | null = null; + private dirReady = false; + private chain: Promise = Promise.resolve(); + private timer: NodeJS.Timeout | null = null; + + constructor(options: LogFileOptions) { + this.opts = { ...DEFAULTS, ...options }; + this.filePath = path.join(this.opts.dir, this.opts.file); + } + + get path(): string { + return this.filePath; + } + + /** Queue one line (without its newline). Never blocks and never throws. */ + write(line: string): void { + const chunk = `${line}\n`; + if (this.pendingBytes + chunk.length > this.opts.maxBufferedBytes) { + this.dropped++; + return; + } + if (this.dropped > 0) this.reportDropped(); + this.pending.push(chunk); + this.pendingBytes += chunk.length; + this.schedule(); + } + + /** Resolves once everything queued before the call is on disk (or reported as failed). */ + flush(): Promise { + if (this.timer) { + clearTimeout(this.timer); + this.timer = null; + } + this.chain = this.chain.then(() => this.drain()); + return this.chain; + } + + /** + * Write whatever is still in memory, synchronously. For the last moment of + * a process (the exit handler), where a promise would never settle. A batch + * whose async append was still running is written again rather than risked: + * a duplicated line at exit is better than a lost one. + */ + flushSync(): void { + if (this.timer) { + clearTimeout(this.timer); + this.timer = null; + } + const data = (this.inFlight ?? '') + this.takePending(); + if (!data) return; + try { + fs.mkdirSync(this.opts.dir, { recursive: true }); + fs.appendFileSync(this.filePath, data); + } catch (err) { + this.opts.onError(`log file write failed: ${errorMessage(err)}`); + } + } + + private schedule(): void { + if (this.timer) return; + this.timer = setTimeout(() => { + this.timer = null; + void this.flush(); + }, this.opts.flushDelayMs); + // A queued log line must never be what keeps a finished process alive. + this.timer.unref?.(); + } + + private takePending(): string { + if (this.dropped > 0) this.reportDropped(); + const data = this.pending.join(''); + this.pending = []; + this.pendingBytes = 0; + return data; + } + + private reportDropped(): void { + const note = `[WARN] [logger] ${this.dropped} log line(s) dropped while the log file could not keep up\n`; + this.dropped = 0; + this.pending.push(note); + this.pendingBytes += note.length; + } + + private async drain(): Promise { + const data = this.takePending(); + if (!data) return; + this.inFlight = data; + try { + await this.ensureDir(); + const bytes = Buffer.byteLength(data); + if (this.size === null) this.size = await this.sizeOnDisk(); + // Same trigger as before: a file already at the cap is rotated before the next append. + if (this.size >= this.opts.maxBytes) await this.rotate(); + await fs.promises.appendFile(this.filePath, data); + this.size += bytes; + } catch (err) { + // The size we track may be wrong after a failure; learn it again next time. + this.size = null; + this.opts.onError(`log file write failed: ${errorMessage(err)}`); + } finally { + this.inFlight = null; + } + } + + private async ensureDir(): Promise { + if (this.dirReady) return; + await fs.promises.mkdir(this.opts.dir, { recursive: true }); + this.dirReady = true; + } + + private async sizeOnDisk(): Promise { + try { + return (await fs.promises.stat(this.filePath)).size; + } catch (err) { + if (isMissing(err)) return 0; + throw err; + } + } + + private async rotate(): Promise { + try { + // Somebody else may have rotated since we last looked. + const actual = await this.sizeOnDisk(); + if (actual < this.opts.maxBytes) { + this.size = actual; + return; + } + for (let i = this.opts.maxFiles - 1; i >= 1; i--) { + const src = i === 1 ? this.filePath : `${this.filePath}.${i - 1}`; + try { + await fs.promises.rename(src, `${this.filePath}.${i}`); + } catch (err) { + if (!isMissing(err)) throw err; + } + } + this.size = 0; + } catch (err) { + this.opts.onError(`log rotation failed: ${errorMessage(err)}`); + // Keep appending to the current file rather than losing the batch. + this.size = await this.sizeOnDisk().catch(() => 0); + } + } +} diff --git a/server/tests/unit/nest/audit-log.logger.test.ts b/server/tests/unit/nest/audit-log.logger.test.ts index 9caba55cf..42bbd12bb 100644 --- a/server/tests/unit/nest/audit-log.logger.test.ts +++ b/server/tests/unit/nest/audit-log.logger.test.ts @@ -1,35 +1,54 @@ /** - * Unit tests for nest/audit/audit-log.logger — AUDIT-LOG-001 through - * AUDIT-LOG-009. The logger is the plain module carved out of the legacy - * services/auditLog.ts; since the quirk-fix pass it has a real severity - * threshold (error < warn < info < debug) against the import-frozen LOG_LEVEL, - * lazy data/logs creation (no import-time mkdir), and console.error fallbacks - * for file-IO failures. It sits inside the src/nest/** coverage gate, so its - * branches are pinned here with fs fully mocked. + * Unit tests for nest/audit/audit-log.logger: AUDIT-LOG-001 through + * AUDIT-LOG-007. The logger ranks error < warn < info < debug against the + * import-frozen LOG_LEVEL, prints every line to the console at once and hands + * the same line, without colour codes, to the buffered file sink. The sink is + * replaced here by a recorder; its own disk behaviour (batching, rotation, + * failures) is pinned in log-file.test.ts. */ import { describe, it, expect, vi, beforeEach } from 'vitest'; -vi.mock('fs', () => { - const mock = { - mkdirSync: vi.fn(), - existsSync: vi.fn(() => false), - statSync: vi.fn(() => ({ size: 0 })), - appendFileSync: vi.fn(), - renameSync: vi.fn(), - }; - return { default: mock, ...mock }; -}); +const sink = vi.hoisted(() => ({ + lines: [] as string[], + options: [] as Array<{ dir: string; file?: string; maxBytes?: number; maxFiles?: number }>, + flush: vi.fn(async () => {}), + flushSync: vi.fn(), +})); -import fs from 'fs'; -import { logInfo, logDebug, logError, logWarn, LOG_LEVEL } from '../../../src/nest/audit/audit-log.logger'; +vi.mock('../../../src/nest/audit/log-file', () => ({ + BufferedLogFile: class { + constructor(options: { dir: string; file?: string; maxBytes?: number; maxFiles?: number }) { + sink.options.push(options); + } + write(line: string): void { + sink.lines.push(line); + } + flush(): Promise { + return sink.flush(); + } + flushSync(): void { + sink.flushSync(); + } + }, +})); -const mocked = vi.mocked(fs); +import path from 'node:path'; +import { + logInfo, + logDebug, + logError, + logWarn, + flushLogFile, + flushLogFileSync, + LOG_LEVEL, +} from '../../../src/nest/audit/audit-log.logger'; +import { resolveDataPaths } from '../../../src/app-config/data-paths'; beforeEach(() => { - vi.clearAllMocks(); vi.restoreAllMocks(); - mocked.existsSync.mockReturnValue(false); - mocked.statSync.mockReturnValue({ size: 0 } as unknown as ReturnType); + sink.lines.length = 0; + sink.flush.mockClear(); + sink.flushSync.mockClear(); }); // tests/setup.ts sets LOG_LEVEL=error before the first import, so the statically @@ -52,12 +71,13 @@ describe('severity threshold (frozen at import)', () => { logDebug('nope'); expect(log).not.toHaveBeenCalled(); expect(warn).not.toHaveBeenCalled(); - expect(mocked.appendFileSync).not.toHaveBeenCalled(); + expect(sink.lines).toEqual([]); logError('boom'); const consoleLine = String(err.mock.calls[0][0]); expect(consoleLine.startsWith('\x1b[31m[ERROR]\x1b[0m ')).toBe(true); expect(consoleLine).toMatch(/ \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2} boom$/); - expect(String(mocked.appendFileSync.mock.calls[0][1])).toMatch(/^\[ERROR\] \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2} boom\n$/); + expect(sink.lines).toHaveLength(1); + expect(sink.lines[0]).toMatch(/^\[ERROR\] \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2} boom$/); }); it('AUDIT-LOG-002: at LOG_LEVEL=debug every level logs with its tag', async () => { @@ -73,7 +93,7 @@ describe('severity threshold (frozen at import)', () => { expect(log.mock.calls.map((c) => String(c[0]).includes('[INFO]') || String(c[0]).includes('[DEBUG]'))).toEqual([true, true]); expect(String(warn.mock.calls[0][0])).toContain('[WARN]'); expect(String(err.mock.calls[0][0])).toContain('[ERROR]'); - expect(mocked.appendFileSync).toHaveBeenCalledTimes(4); + expect(sink.lines.map((line) => line.split(' ')[0])).toEqual(['[INFO]', '[DEBUG]', '[WARN]', '[ERROR]']); } finally { vi.unstubAllEnvs(); vi.resetModules(); @@ -91,13 +111,14 @@ describe('severity threshold (frozen at import)', () => { expect(log).toHaveBeenCalledTimes(1); expect(String(log.mock.calls[0][0])).toContain('[INFO]'); expect(warn).toHaveBeenCalledTimes(1); + expect(sink.lines).toHaveLength(2); } finally { vi.unstubAllEnvs(); vi.resetModules(); } }); - it('AUDIT-LOG-004: the freeze happens at first import — LOG_LEVEL reflects the env then', async () => { + it('AUDIT-LOG-004: the freeze happens at first import, so LOG_LEVEL reflects the env then', async () => { const fresh = await freshLogger('debug'); try { expect(fresh.LOG_LEVEL).toBe('debug'); @@ -109,60 +130,27 @@ describe('severity threshold (frozen at import)', () => { }); }); -describe('lazy logs dir + rotation + resilience', () => { - it('AUDIT-LOG-005: data/logs is created lazily on the first write, not at import', async () => { - const fresh = await freshLogger('info'); - try { - mocked.mkdirSync.mockClear(); - expect(mocked.mkdirSync).not.toHaveBeenCalled(); - vi.spyOn(console, 'log').mockImplementation(() => {}); - fresh.logInfo('first write'); - expect(mocked.mkdirSync).toHaveBeenCalledTimes(1); - fresh.logInfo('second write'); - expect(mocked.mkdirSync).toHaveBeenCalledTimes(1); // memoized - } finally { - vi.unstubAllEnvs(); - vi.resetModules(); - } +describe('the file sink', () => { + it('AUDIT-LOG-005: writes trek.log in the data layout logs dir, rotating at 10 MB over 5 files', () => { + expect(sink.options[0]).toMatchObject({ + dir: resolveDataPaths().logsDir, + file: 'trek.log', + maxBytes: 10 * 1024 * 1024, + maxFiles: 5, + }); + expect(path.basename(resolveDataPaths().logsDir)).toBe('logs'); }); - it('AUDIT-LOG-006: rotates trek.log through .1… in descending order once the cap is hit', () => { + it('AUDIT-LOG-006: the file line carries no colour codes', () => { vi.spyOn(console, 'error').mockImplementation(() => {}); - mocked.existsSync.mockReturnValue(true); - mocked.statSync.mockReturnValue({ size: 10 * 1024 * 1024 } as unknown as ReturnType); - logError('rotate me'); - // MAX_LOG_FILES=5 → renames .3→.4, .2→.3, .1→.2, trek.log→.1 (descending). - expect(mocked.renameSync).toHaveBeenCalledTimes(4); - const dsts = mocked.renameSync.mock.calls.map((c) => String(c[1])); - expect(dsts[0].endsWith('trek.log.4')).toBe(true); - expect(dsts[3].endsWith('trek.log.1')).toBe(true); - expect(String(mocked.renameSync.mock.calls[3][0]).endsWith('trek.log')).toBe(true); + logError('plain'); + expect(sink.lines[0]).not.toContain('\x1b['); }); - it('AUDIT-LOG-007: no rotation below the size cap', () => { - vi.spyOn(console, 'error').mockImplementation(() => {}); - mocked.existsSync.mockReturnValue(true); - mocked.statSync.mockReturnValue({ size: 10 } as unknown as ReturnType); - logError('small'); - expect(mocked.renameSync).not.toHaveBeenCalled(); - expect(mocked.appendFileSync).toHaveBeenCalledTimes(1); - }); - - it('AUDIT-LOG-008: file-write failures never throw and leave a console.error trace', () => { - const err = vi.spyOn(console, 'error').mockImplementation(() => {}); - mocked.appendFileSync.mockImplementation(() => { throw new Error('disk full'); }); - expect(() => logError('still up')).not.toThrow(); - // First call is the [ERROR] line itself, second is the fallback trace. - expect(err).toHaveBeenCalledTimes(2); - expect(String(err.mock.calls[1][0])).toBe('[logger] log file write failed: disk full'); - }); - - it('AUDIT-LOG-009: rotation failures are traced and the write still goes through', () => { - const err = vi.spyOn(console, 'error').mockImplementation(() => {}); - mocked.existsSync.mockReturnValue(true); - mocked.statSync.mockImplementation(() => { throw new Error('stat broke'); }); - expect(() => logError('resilient')).not.toThrow(); - expect(String(err.mock.calls[1][0])).toBe('[logger] log rotation failed: stat broke'); - expect(mocked.appendFileSync).toHaveBeenCalledTimes(1); + it('AUDIT-LOG-007: flushLogFile and flushLogFileSync reach the sink', async () => { + await flushLogFile(); + flushLogFileSync(); + expect(sink.flush).toHaveBeenCalledTimes(1); + expect(sink.flushSync).toHaveBeenCalledTimes(1); }); }); diff --git a/server/tests/unit/nest/log-file.test.ts b/server/tests/unit/nest/log-file.test.ts new file mode 100644 index 000000000..1361e12f2 --- /dev/null +++ b/server/tests/unit/nest/log-file.test.ts @@ -0,0 +1,155 @@ +/** + * BufferedLogFile (nest/audit/log-file.ts), the file half of the server log, + * against a real temporary directory: LOGFILE-001 through LOGFILE-009. + * + * What it promises: a write never touches the disk on the caller's turn, + * queued lines reach the file in order through one append per batch, the file + * rotates the way trek.log always did (`.1` newest, `maxFiles` in total), a + * rotation another process already did is not repeated, and a failing disk is + * reported instead of thrown. + */ +import { describe, it, expect, afterEach, vi } from 'vitest'; +import fs from 'node:fs'; +import os from 'node:os'; +import path from 'node:path'; +import { BufferedLogFile } from '../../../src/nest/audit/log-file'; + +const dirs: string[] = []; + +function tmpDir(): string { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'trek-logfile-')); + dirs.push(dir); + return dir; +} + +function read(file: string): string { + return fs.readFileSync(file, 'utf8'); +} + +afterEach(() => { + vi.restoreAllMocks(); + for (const dir of dirs.splice(0)) fs.rmSync(dir, { recursive: true, force: true }); +}); + +describe('BufferedLogFile', () => { + it('LOGFILE-001: a write returns before anything reaches the disk', () => { + const dir = path.join(tmpDir(), 'logs'); + const sink = new BufferedLogFile({ dir, onError: vi.fn() }); + sink.write('first'); + expect(fs.existsSync(dir)).toBe(false); + }); + + it('LOGFILE-002: flush creates the directory and appends every queued line in order', async () => { + const dir = path.join(tmpDir(), 'logs'); + const sink = new BufferedLogFile({ dir, onError: vi.fn() }); + sink.write('one'); + sink.write('two'); + await sink.flush(); + sink.write('three'); + await sink.flush(); + expect(read(path.join(dir, 'trek.log'))).toBe('one\ntwo\nthree\n'); + }); + + it('LOGFILE-003: one batch is one append, however many lines it holds', async () => { + const dir = tmpDir(); + const append = vi.spyOn(fs.promises, 'appendFile'); + const sink = new BufferedLogFile({ dir, onError: vi.fn() }); + for (let i = 0; i < 100; i++) sink.write(`line ${i}`); + await sink.flush(); + expect(append).toHaveBeenCalledTimes(1); + expect(read(sink.path).split('\n')).toHaveLength(101); + }); + + it('LOGFILE-004: the queued lines flush by themselves after the batching delay', async () => { + const dir = tmpDir(); + const sink = new BufferedLogFile({ dir, flushDelayMs: 5, onError: vi.fn() }); + sink.write('later'); + await vi.waitFor(() => expect(fs.existsSync(sink.path) && read(sink.path)).toBe('later\n')); + }); + + it('LOGFILE-005: a file at the cap rotates to .1 and older files shift, the oldest falling off', async () => { + const dir = tmpDir(); + const file = path.join(dir, 'trek.log'); + fs.writeFileSync(file, 'x'.repeat(100)); + fs.writeFileSync(`${file}.1`, 'one'); + fs.writeFileSync(`${file}.2`, 'two'); + const sink = new BufferedLogFile({ dir, maxBytes: 100, maxFiles: 3, onError: vi.fn() }); + sink.write('fresh'); + await sink.flush(); + expect(read(file)).toBe('fresh\n'); + expect(read(`${file}.1`)).toBe('x'.repeat(100)); + expect(read(`${file}.2`)).toBe('one'); + expect(fs.existsSync(`${file}.3`)).toBe(false); + }); + + it('LOGFILE-006: below the cap nothing rotates, and the size it tracks triggers the next rotation', async () => { + const dir = tmpDir(); + const sink = new BufferedLogFile({ dir, maxBytes: 10, onError: vi.fn() }); + sink.write('12345'); + await sink.flush(); + expect(fs.existsSync(`${sink.path}.1`)).toBe(false); + sink.write('67890'); + await sink.flush(); + // 12 bytes on disk now, past the cap of 10: the next batch rotates first. + sink.write('next'); + await sink.flush(); + expect(read(`${sink.path}.1`)).toBe('12345\n67890\n'); + expect(read(sink.path)).toBe('next\n'); + }); + + it('LOGFILE-007: a rotation another process already did is not repeated', async () => { + const dir = tmpDir(); + const file = path.join(dir, 'trek.log'); + const sink = new BufferedLogFile({ dir, maxBytes: 10, onError: vi.fn() }); + sink.write('0123456789'); + await sink.flush(); + // The other process rotates and starts a fresh file. + fs.renameSync(file, `${file}.1`); + fs.writeFileSync(file, 'theirs\n'); + sink.write('mine'); + await sink.flush(); + expect(read(file)).toBe('theirs\nmine\n'); + expect(read(`${file}.1`)).toBe('0123456789\n'); + expect(fs.existsSync(`${file}.2`)).toBe(false); + }); + + it('LOGFILE-008: a failing append is reported, never thrown, and the next batch tries again', async () => { + const dir = tmpDir(); + const onError = vi.fn(); + const sink = new BufferedLogFile({ dir, onError }); + vi.spyOn(fs.promises, 'appendFile').mockRejectedValueOnce(new Error('disk full')); + sink.write('lost'); + await expect(sink.flush()).resolves.toBeUndefined(); + expect(onError).toHaveBeenCalledWith('log file write failed: disk full'); + sink.write('kept'); + await sink.flush(); + expect(read(sink.path)).toBe('kept\n'); + }); + + it('LOGFILE-009: flushSync writes what is queued at once, for the exit handler', () => { + const dir = path.join(tmpDir(), 'logs'); + const sink = new BufferedLogFile({ dir, onError: vi.fn() }); + sink.write('last words'); + sink.flushSync(); + expect(read(sink.path)).toBe('last words\n'); + sink.flushSync(); + expect(read(sink.path)).toBe('last words\n'); + }); + + it('LOGFILE-010: past the memory ceiling lines are dropped and the count is logged once there is room', async () => { + const dir = tmpDir(); + const sink = new BufferedLogFile({ dir, maxBufferedBytes: 12, onError: vi.fn() }); + sink.write('aaaaa'); // 6 bytes queued + sink.write('bbbbb'); // 12 bytes queued, at the ceiling + sink.write('ccccc'); // dropped + await sink.flush(); + sink.write('d'); + await sink.flush(); + const lines = read(sink.path).trim().split('\n'); + expect(lines[0]).toBe('aaaaa'); + expect(lines[1]).toBe('bbbbb'); + expect(lines).not.toContain('ccccc'); + expect(lines.some((line) => line.includes('1 log line(s) dropped'))).toBe(true); + expect(lines.at(-1)).toBe('d'); + }); +});