diff --git a/packages/logger/src/index.test.ts b/packages/logger/src/index.test.ts index 076fd74c293..78d88313267 100644 --- a/packages/logger/src/index.test.ts +++ b/packages/logger/src/index.test.ts @@ -216,4 +216,131 @@ describe('Logger', () => { ) }) }) + + describe('structured serialization safety', () => { + const createEnabledLogger = () => + new Logger('Test', { enabled: true, colorize: false, logLevel: LogLevel.DEBUG }) + + test('should emit a line instead of throwing on cyclic metadata', () => { + const cyclic: Record = { id: 'x' } + cyclic.self = cyclic + + expect(() => createEnabledLogger().info('hello', cyclic)).not.toThrow() + expect(consoleLogSpy).toHaveBeenCalledTimes(1) + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('hello') + expect(parsed.id).toBe('x') + expect(parsed.self.self).toBe('[Circular]') + }) + + test('should emit a line instead of throwing on BigInt metadata', () => { + expect(() => createEnabledLogger().error('boom', { size: 10n })).not.toThrow() + expect(consoleErrorSpy).toHaveBeenCalledTimes(1) + const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('boom') + expect(parsed.size).toBe('10') + }) + + test('should fall back to a minimal entry when a value cannot be serialized at all', () => { + const hostile = { + get boom() { + throw new Error('getter exploded') + }, + } + + expect(() => createEnabledLogger().info('hello', hostile)).not.toThrow() + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('hello') + expect(parsed.module).toBe('Test') + expect(parsed.serializationError).toBe(true) + }) + + test('should not throw when withMetadata receives a throwing getter', () => { + const hostile = { + safe: 'kept', + get boom() { + throw new Error('getter exploded') + }, + } as unknown as Parameters[0] + + let child: Logger | undefined + expect(() => { + child = createEnabledLogger().withMetadata(hostile) + }).not.toThrow() + + expect(() => child?.info('hello')).not.toThrow() + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('hello') + expect(parsed.safe).toBe('kept') + expect(parsed.boom).toBe('[Unreadable]') + }) + + test('should keep repeated references that are not cycles', () => { + const shared = { s: 'REAL_DATA', n: 42 } + const payload = { p: shared, q: shared, arr: [shared, shared], big: 1n } as unknown as object + + createEnabledLogger().info('hello', payload) + + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.p).toEqual({ s: 'REAL_DATA', n: 42 }) + expect(parsed.q).toEqual({ s: 'REAL_DATA', n: 42 }) + expect(parsed.arr).toEqual([ + { s: 'REAL_DATA', n: 42 }, + { s: 'REAL_DATA', n: 42 }, + ]) + expect(parsed.big).toBe('1') + }) + + test('should still mark a genuine cycle as circular', () => { + const cyclic: Record = { name: 'root' } + cyclic.self = cyclic + const payload = { cyclic, big: 1n } as unknown as object + + createEnabledLogger().info('hello', payload) + + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.cyclic.name).toBe('root') + expect(parsed.cyclic.self).toBe('[Circular]') + }) + + test('should not throw when retained metadata has a throwing toJSON', () => { + const hostile = { + evil: { + toJSON() { + throw new Error('toJSON exploded') + }, + }, + } as unknown as Parameters[0] + + const child = createEnabledLogger().withMetadata(hostile) + + expect(() => child.info('hello')).not.toThrow() + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('hello') + expect(parsed.module).toBe('Test') + expect(parsed.serializationError).toBe(true) + expect(parsed.evil).toBeUndefined() + }) + + test('should not throw when withMetadata receives a hostile proxy', () => { + const hostile = new Proxy( + {}, + { + ownKeys() { + throw new Error('ownKeys exploded') + }, + } + ) as Parameters[0] + + let child: Logger | undefined + expect(() => { + child = createEnabledLogger().withMetadata(hostile) + }).not.toThrow() + + expect(() => child?.info('hello')).not.toThrow() + const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string) + expect(parsed.message).toBe('hello') + expect(parsed.metadataError).toBe(true) + }) + }) }) diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index 25e6e3f9ae3..47da5e03f0c 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -139,6 +139,110 @@ const formatObject = (obj: unknown, isDev: boolean): string => { } } +/** Merges caller-supplied log arguments into the structured entry. */ +const mergeArgs = (entry: Record, args: unknown[]): Record => { + for (const arg of args) { + if (arg === null || arg === undefined) continue + if (arg instanceof Error) { + entry.error = arg.message + entry.stack = arg.stack + } else if (typeof arg === 'object') { + Object.assign(entry, arg) + } else { + entry.extra = arg + } + } + return entry +} + +/** JSON replacer that tolerates cyclic references and BigInt values. */ +const tolerantReplacer = () => { + const ancestors: object[] = [] + return function (this: unknown, _key: string, value: unknown): unknown { + if (typeof value === 'bigint') return value.toString() + if (value === null || typeof value !== 'object') return value + /** + * Track the ancestor path, not every object ever visited. `this` is the + * object holding the current key, so unwinding to it drops the siblings we + * have finished descending. A set of everything seen would label the second + * appearance of a merely repeated reference `[Circular]` and discard real + * data, since a payload that references one object twice has no cycle. + */ + while (ancestors.length > 0 && ancestors[ancestors.length - 1] !== this) ancestors.pop() + if (ancestors.includes(value)) return '[Circular]' + ancestors.push(value) + return value + } +} + +/** + * Builds and serializes a production log entry without ever throwing. + * + * Caller-supplied arguments are merged in verbatim, so a cyclic reference, a + * BigInt, or a throwing getter would otherwise raise inside the caller's code + * path — losing the line and aborting whatever was being logged about. A + * logger must never be able to break its caller. + */ +const serializeEntry = (base: Record, args: unknown[]): string => { + try { + return JSON.stringify(mergeArgs({ ...base }, args)) + } catch {} + + try { + return JSON.stringify(mergeArgs({ ...base }, args), tolerantReplacer()) + } catch {} + + return minimalEntry(base) +} + +/** + * Last-resort entry built only from fields this module controls. + * + * A replacer cannot rescue a throwing `toJSON`, because `JSON.stringify` invokes + * it before the replacer ever sees the value. So the final fallback drops every + * caller-supplied value instead of re-serializing it, and passes strings through + * only when they are already strings — coercing would re-enter hostile + * `toString`. What remains cannot throw. + */ +const minimalEntry = (base: Record): string => { + const asString = (value: unknown) => (typeof value === 'string' ? value : '[Unserializable]') + return JSON.stringify({ + timestamp: asString(base.timestamp), + level: asString(base.level), + module: asString(base.module), + message: asString(base.message), + serializationError: true, + }) +} + +/** + * Copies caller-supplied metadata into a plain object without ever throwing. + * + * `LoggerMetadata` is structurally typed, so nothing stops a caller from handing + * over an object carrying a throwing getter or a hostile proxy. A spread invokes + * those traps, so the copy degrades key-by-key and finally to a marker rather + * than raising inside the caller's code path. + */ +const materializeMetadata = (metadata: LoggerMetadata): LoggerMetadata => { + try { + return { ...metadata } + } catch {} + + const safe: LoggerMetadata = {} + try { + for (const key of Object.keys(metadata)) { + try { + safe[key] = metadata[key] + } catch { + safe[key] = '[Unreadable]' + } + } + return safe + } catch {} + + return { metadataError: true } +} + /** * Logger class for standardized console logging * @@ -191,7 +295,7 @@ export class Logger { child.module = this.module child.config = this.config child.isDev = this.isDev - child.metadata = { ...this.metadata, ...metadata } + child.metadata = { ...this.metadata, ...materializeMetadata(metadata) } return child } @@ -280,33 +384,17 @@ export class Logger { } } else { // Structured JSON for production — CloudWatch Log Insights auto-parses JSON lines - const entry: Record = { + const base: Record = { timestamp, level, module: this.module, message, } for (const [k, v] of metadataEntries) { - entry[k] = v - } - // Merge extra args into the entry - for (const arg of args) { - if ( - arg !== null && - arg !== undefined && - typeof arg === 'object' && - !(arg instanceof Error) - ) { - Object.assign(entry, arg) - } else if (arg instanceof Error) { - entry.error = arg.message - entry.stack = arg.stack - } else if (arg !== null && arg !== undefined) { - entry.extra = arg - } + base[k] = v } - const line = JSON.stringify(entry) + const line = serializeEntry(base, args) if (level === LogLevel.ERROR) { console.error(line) } else {