mirror of
https://github.com/mauriceboe/TREK.git
synced 2026-10-24 16:03:02 +00:00
perf(server): write the file log in batches off the event loop
Every log line ran existsSync, statSync and appendFileSync on the event loop before it returned. On a slow data volume (an SMB or NFS bind mount on a NAS) that stalled every request that logged, and rotation renamed files without checking whether another process sharing data/logs had rotated already. The file half of the logger is now BufferedLogFile: a line is queued in memory and the queue goes out with one appendFile per batch, through a single serial chain, so no append runs while files are being renamed. The files and the rotation are the same as before (trek.log rotates to .1 at 10 MB, five files in total), but the size is re-read before a rotation and a file another process already rotated is left alone. A stalled disk costs dropped lines with a count instead of unbounded memory, a failed write is reported instead of thrown, and index.ts writes whatever is still queued synchronously when the process exits.
This commit is contained in:
Maurice
@@ -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<void> {
|
||||
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<typeof fs.statSync>);
|
||||
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<typeof fs.statSync>);
|
||||
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<typeof fs.statSync>);
|
||||
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);
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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');
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user