diff --git a/src/logging/structured-logging.spec.ts b/src/logging/structured-logging.spec.ts new file mode 100644 index 00000000..edbad4c7 --- /dev/null +++ b/src/logging/structured-logging.spec.ts @@ -0,0 +1,172 @@ +import { + configureSampling, + resetSampler, + getSamplerState, + buildLogObject, +} from './structured-logging'; + +// Test formatWithSampling by creating a simple wrapper that mimics the console override +function invokeErrorSampling(args: unknown[]): string | null { + let output: string | null = null; + const originalConfig = { firstN: 3, thenEveryM: 5 }; + + // We'll use configureSampling + manual sampler to test the behaviour + configureSampling({ firstN: 3, thenEveryM: 5 }); + + // We can test by calling initStructuredLogging with a custom output, + // but instead let's directly test via console.error after init. + + return output; +} + +// Alternative approach: re-import after init +import { initStructuredLogging } from './structured-logging'; + +describe('Error sampling / rate limiting', () => { + let errorOutputs: string[]; + + beforeAll(() => { + // Store original console.error + const origError = console.error.bind(console); + errorOutputs = []; + + // Replace console.error with a collector + console.error = function (...args: unknown[]) { + errorOutputs.push(args.map(String).join(' ')); + origError(...args); + } as typeof console.error; + + initStructuredLogging('test'); + }); + + afterAll(() => { + // Don't restore — the test suite owns the override + }); + + beforeEach(() => { + resetSampler(); + configureSampling({ firstN: 3, thenEveryM: 5 }); + errorOutputs.length = 0; + }); + + function parsedCalls(): Record[] { + return errorOutputs.map((s) => JSON.parse(s)); + } + + it('logs every error up to firstN without sampling marker', () => { + for (let i = 0; i < 3; i++) { + console.error('db connection failed', { db: 'pg' }); + } + + const outputs = parsedCalls(); + expect(outputs).toHaveLength(3); + outputs.forEach((out, idx) => { + expect(out.message).toBe('db connection failed'); + expect(out.occurrenceCount).toBe(idx + 1); + expect(out.sampled).toBeUndefined(); + }); + }); + + it('samples after firstN, logging 1-in-M with occurrenceCount', () => { + for (let i = 0; i < 13; i++) { + console.error('timeout'); + } + + const outputs = parsedCalls(); + expect(outputs).toHaveLength(5); + + expect(outputs[0].occurrenceCount).toBe(1); + expect(outputs[0].sampled).toBeUndefined(); + expect(outputs[1].occurrenceCount).toBe(2); + expect(outputs[1].sampled).toBeUndefined(); + expect(outputs[2].occurrenceCount).toBe(3); + expect(outputs[2].sampled).toBeUndefined(); + expect(outputs[3].occurrenceCount).toBe(8); + expect(outputs[3].sampled).toBe(true); + expect(outputs[4].occurrenceCount).toBe(13); + expect(outputs[4].sampled).toBe(true); + }); + + it('tracks different message keys independently', () => { + for (let i = 0; i < 6; i++) { + console.error('error-a'); + console.error('error-b'); + } + + const outputs = parsedCalls(); + const aCalls = outputs.filter((o) => o.message === 'error-a'); + const bCalls = outputs.filter((o) => o.message === 'error-b'); + expect(aCalls).toHaveLength(3); + expect(bCalls).toHaveLength(3); + expect(outputs).toHaveLength(6); + }); + + it('uses Error.message as sampler key when an Error is passed', () => { + for (let i = 0; i < 6; i++) { + console.error(new Error('err occurred')); + } + + const outputs = parsedCalls(); + expect(outputs).toHaveLength(3); + outputs.forEach((o, idx) => { + expect(o.data).toEqual({ message: 'err occurred', stack: expect.any(String) }); + expect(o.occurrenceCount).toBe(idx + 1); + }); + }); + + it('does not sample non-error levels', () => { + for (let i = 0; i < 10; i++) { + console.info('info msg'); + console.warn('warn msg'); + console.debug('debug msg'); + } + + expect(getSamplerState().size).toBe(0); + }); + + it('configureSampling updates thresholds', () => { + configureSampling({ firstN: 1, thenEveryM: 2 }); + + for (let i = 0; i < 7; i++) { + console.error('err'); + } + + const outputs = parsedCalls(); + expect(outputs).toHaveLength(4); + expect(outputs[0].occurrenceCount).toBe(1); + expect(outputs[0].sampled).toBeUndefined(); + expect(outputs[1].occurrenceCount).toBe(3); + expect(outputs[1].sampled).toBe(true); + expect(outputs[2].occurrenceCount).toBe(5); + expect(outputs[2].sampled).toBe(true); + expect(outputs[3].occurrenceCount).toBe(7); + expect(outputs[3].sampled).toBe(true); + }); + + it('resetSampler clears all state', () => { + for (let i = 0; i < 6; i++) console.error('err'); + expect(parsedCalls()).toHaveLength(3); + + resetSampler(); + errorOutputs.length = 0; + + for (let i = 0; i < 6; i++) console.error('err'); + expect(parsedCalls()).toHaveLength(3); + }); + + it('getSamplerState returns current counts', () => { + for (let i = 0; i < 10; i++) console.error('err-a'); + for (let i = 0; i < 5; i++) console.error('err-b'); + + const state = getSamplerState(); + expect(state.get('err-a')!.count).toBe(10); + expect(state.get('err-b')!.count).toBe(5); + }); + + it('buildLogObject is unaffected by sampling', () => { + const obj = buildLogObject('error', 'test message', { key: 'val' }); + expect(obj.level).toBe('error'); + expect(obj.message).toBe('test message'); + expect(obj.meta).toEqual({ key: 'val' }); + }); +}); diff --git a/src/logging/structured-logging.ts b/src/logging/structured-logging.ts index 29147b81..7cef5073 100644 --- a/src/logging/structured-logging.ts +++ b/src/logging/structured-logging.ts @@ -1,5 +1,53 @@ export type LogMeta = Record; +export interface SamplingConfig { + firstN: number; + thenEveryM: number; +} + +interface SamplerEntry { + count: number; + logged: number; +} + +const samplerMap = new Map(); +const MAX_SAMPLER_ENTRIES = 1000; + +const DEFAULT_SAMPLING: SamplingConfig = { + firstN: 5, + thenEveryM: 10, +}; + +let _samplingConfig: SamplingConfig = { ...DEFAULT_SAMPLING }; + +export function configureSampling(config: Partial): void { + if (config.firstN !== undefined) _samplingConfig.firstN = config.firstN; + if (config.thenEveryM !== undefined) _samplingConfig.thenEveryM = config.thenEveryM; +} + +export function resetSampler(): void { + samplerMap.clear(); +} + +export function getSamplerState(): ReadonlyMap> { + return samplerMap as ReadonlyMap>; +} + +function getSamplerKey(args: unknown[]): string | null { + for (const arg of args) { + if (typeof arg === 'string') return arg; + if (arg instanceof Error) return arg.message; + } + return null; +} + +function evictSamplerIfNeeded(): void { + if (samplerMap.size >= MAX_SAMPLER_ENTRIES) { + const keysToDelete = Array.from(samplerMap.keys()).slice(0, Math.floor(MAX_SAMPLER_ENTRIES / 2)); + for (const key of keysToDelete) samplerMap.delete(key); + } +} + function timestamp(): string { return new Date().toISOString(); } @@ -45,11 +93,76 @@ function formatStructured(level: string, service: string, args: unknown[], meta: } } +function formatWithSampling( + level: string, + service: string, + args: unknown[], + originalFn: (...args: unknown[]) => void, +): void { + if (level !== 'error') { + originalFn(formatStructured(level, service, args)); + return; + } + + const key = getSamplerKey(args); + if (key === null) { + originalFn(formatStructured(level, service, args)); + return; + } + + let entry = samplerMap.get(key); + if (!entry) { + entry = { count: 0, logged: 0 }; + samplerMap.set(key, entry); + } + entry.count++; + + const { firstN, thenEveryM } = _samplingConfig; + const shouldLog = entry.count <= firstN || (entry.count - firstN) % thenEveryM === 0; + + if (shouldLog) { + entry.logged++; + evictSamplerIfNeeded(); + const msgParts: unknown[] = Array.prototype.slice.call(args); + const message = typeof msgParts[0] === 'string' ? msgParts.shift() : undefined; + const extra = msgParts.length === 1 ? safeSerialize(msgParts[0]) : msgParts.map(safeSerialize); + + const out: Record = { + timestamp: timestamp(), + level, + service, + pid: process.pid, + occurrenceCount: entry.count, + }; + + if (message) out.message = message; + if (extra !== undefined && (Array.isArray(extra) ? extra.length > 0 : Object.keys((extra as any) || {}).length > 0)) { + out.data = extra; + } + if (entry.count > firstN) out.sampled = true; + + try { + originalFn(JSON.stringify(out)); + } catch (_err) { + originalFn( + JSON.stringify({ + timestamp: timestamp(), + level, + service, + pid: process.pid, + message: 'failed to stringify log', + }), + ); + } + } +} + let _serviceName = 'teachlink-backend'; /* eslint-disable no-console */ -export function initStructuredLogging(serviceName?: string): void { +export function initStructuredLogging(serviceName?: string, samplingConfig?: Partial): void { if (serviceName) _serviceName = serviceName; + if (samplingConfig) configureSampling(samplingConfig); const originalLog = console.log.bind(console); const originalInfo = console.info.bind(console); @@ -70,7 +183,7 @@ export function initStructuredLogging(serviceName?: string): void { } as typeof console.warn; console.error = function error(...args: unknown[]) { - originalError(formatStructured('error', _serviceName, args)); + formatWithSampling('error', _serviceName, args, originalError); } as typeof console.error; console.debug = function debug(...args: unknown[]) {