Skip to content

Commit 0ae09c1

Browse files
authored
fix(logger): never let structured serialization throw into the caller (#6331)
* fix(logger): never let structured serialization throw into the caller In production the JSON branch merged caller-supplied arguments into the log entry and stringified it with no error handling. A cyclic reference, a BigInt, or a throwing getter in that metadata raised a TypeError out of `logger.info` and friends: the line was lost and the caller's code path aborted. Dev was unaffected — the colorized branch already routes objects through `formatObject`, which catches — so this class of bug is invisible locally and only surfaces in production, where it reads as structured logs disappearing while raw stack traces keep shipping. Build and serialize through `serializeEntry`, which falls back to a cycle/BigInt-tolerant replacer and then to a minimal entry flagged with `serializationError`. * fix(logger): keep hostile child metadata from throwing into the caller * fix(logger): keep a throwing toJSON from escaping the final fallback * fix(logger): keep repeated references out of the circular-reference fallback
1 parent 2ab6be6 commit 0ae09c1

2 files changed

Lines changed: 235 additions & 20 deletions

File tree

packages/logger/src/index.test.ts

Lines changed: 127 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -246,4 +246,131 @@ describe('Logger', () => {
246246
)
247247
})
248248
})
249+
250+
describe('structured serialization safety', () => {
251+
const createEnabledLogger = () =>
252+
new Logger('Test', { enabled: true, colorize: false, logLevel: LogLevel.DEBUG })
253+
254+
test('should emit a line instead of throwing on cyclic metadata', () => {
255+
const cyclic: Record<string, unknown> = { id: 'x' }
256+
cyclic.self = cyclic
257+
258+
expect(() => createEnabledLogger().info('hello', cyclic)).not.toThrow()
259+
expect(consoleLogSpy).toHaveBeenCalledTimes(1)
260+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
261+
expect(parsed.message).toBe('hello')
262+
expect(parsed.id).toBe('x')
263+
expect(parsed.self.self).toBe('[Circular]')
264+
})
265+
266+
test('should emit a line instead of throwing on BigInt metadata', () => {
267+
expect(() => createEnabledLogger().error('boom', { size: 10n })).not.toThrow()
268+
expect(consoleErrorSpy).toHaveBeenCalledTimes(1)
269+
const parsed = JSON.parse(consoleErrorSpy.mock.calls[0][0] as string)
270+
expect(parsed.message).toBe('boom')
271+
expect(parsed.size).toBe('10')
272+
})
273+
274+
test('should fall back to a minimal entry when a value cannot be serialized at all', () => {
275+
const hostile = {
276+
get boom() {
277+
throw new Error('getter exploded')
278+
},
279+
}
280+
281+
expect(() => createEnabledLogger().info('hello', hostile)).not.toThrow()
282+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
283+
expect(parsed.message).toBe('hello')
284+
expect(parsed.module).toBe('Test')
285+
expect(parsed.serializationError).toBe(true)
286+
})
287+
288+
test('should not throw when withMetadata receives a throwing getter', () => {
289+
const hostile = {
290+
safe: 'kept',
291+
get boom() {
292+
throw new Error('getter exploded')
293+
},
294+
} as unknown as Parameters<Logger['withMetadata']>[0]
295+
296+
let child: Logger | undefined
297+
expect(() => {
298+
child = createEnabledLogger().withMetadata(hostile)
299+
}).not.toThrow()
300+
301+
expect(() => child?.info('hello')).not.toThrow()
302+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
303+
expect(parsed.message).toBe('hello')
304+
expect(parsed.safe).toBe('kept')
305+
expect(parsed.boom).toBe('[Unreadable]')
306+
})
307+
308+
test('should keep repeated references that are not cycles', () => {
309+
const shared = { s: 'REAL_DATA', n: 42 }
310+
const payload = { p: shared, q: shared, arr: [shared, shared], big: 1n } as unknown as object
311+
312+
createEnabledLogger().info('hello', payload)
313+
314+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
315+
expect(parsed.p).toEqual({ s: 'REAL_DATA', n: 42 })
316+
expect(parsed.q).toEqual({ s: 'REAL_DATA', n: 42 })
317+
expect(parsed.arr).toEqual([
318+
{ s: 'REAL_DATA', n: 42 },
319+
{ s: 'REAL_DATA', n: 42 },
320+
])
321+
expect(parsed.big).toBe('1')
322+
})
323+
324+
test('should still mark a genuine cycle as circular', () => {
325+
const cyclic: Record<string, unknown> = { name: 'root' }
326+
cyclic.self = cyclic
327+
const payload = { cyclic, big: 1n } as unknown as object
328+
329+
createEnabledLogger().info('hello', payload)
330+
331+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
332+
expect(parsed.cyclic.name).toBe('root')
333+
expect(parsed.cyclic.self).toBe('[Circular]')
334+
})
335+
336+
test('should not throw when retained metadata has a throwing toJSON', () => {
337+
const hostile = {
338+
evil: {
339+
toJSON() {
340+
throw new Error('toJSON exploded')
341+
},
342+
},
343+
} as unknown as Parameters<Logger['withMetadata']>[0]
344+
345+
const child = createEnabledLogger().withMetadata(hostile)
346+
347+
expect(() => child.info('hello')).not.toThrow()
348+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
349+
expect(parsed.message).toBe('hello')
350+
expect(parsed.module).toBe('Test')
351+
expect(parsed.serializationError).toBe(true)
352+
expect(parsed.evil).toBeUndefined()
353+
})
354+
355+
test('should not throw when withMetadata receives a hostile proxy', () => {
356+
const hostile = new Proxy(
357+
{},
358+
{
359+
ownKeys() {
360+
throw new Error('ownKeys exploded')
361+
},
362+
}
363+
) as Parameters<Logger['withMetadata']>[0]
364+
365+
let child: Logger | undefined
366+
expect(() => {
367+
child = createEnabledLogger().withMetadata(hostile)
368+
}).not.toThrow()
369+
370+
expect(() => child?.info('hello')).not.toThrow()
371+
const parsed = JSON.parse(consoleLogSpy.mock.calls[0][0] as string)
372+
expect(parsed.message).toBe('hello')
373+
expect(parsed.metadataError).toBe(true)
374+
})
375+
})
249376
})

packages/logger/src/index.ts

Lines changed: 108 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -154,6 +154,110 @@ const formatObject = (obj: unknown, isDev: boolean): string => {
154154
}
155155
}
156156

157+
/** Merges caller-supplied log arguments into the structured entry. */
158+
const mergeArgs = (entry: Record<string, unknown>, args: unknown[]): Record<string, unknown> => {
159+
for (const arg of args) {
160+
if (arg === null || arg === undefined) continue
161+
if (arg instanceof Error) {
162+
entry.error = arg.message
163+
entry.stack = arg.stack
164+
} else if (typeof arg === 'object') {
165+
Object.assign(entry, arg)
166+
} else {
167+
entry.extra = arg
168+
}
169+
}
170+
return entry
171+
}
172+
173+
/** JSON replacer that tolerates cyclic references and BigInt values. */
174+
const tolerantReplacer = () => {
175+
const ancestors: object[] = []
176+
return function (this: unknown, _key: string, value: unknown): unknown {
177+
if (typeof value === 'bigint') return value.toString()
178+
if (value === null || typeof value !== 'object') return value
179+
/**
180+
* Track the ancestor path, not every object ever visited. `this` is the
181+
* object holding the current key, so unwinding to it drops the siblings we
182+
* have finished descending. A set of everything seen would label the second
183+
* appearance of a merely repeated reference `[Circular]` and discard real
184+
* data, since a payload that references one object twice has no cycle.
185+
*/
186+
while (ancestors.length > 0 && ancestors[ancestors.length - 1] !== this) ancestors.pop()
187+
if (ancestors.includes(value)) return '[Circular]'
188+
ancestors.push(value)
189+
return value
190+
}
191+
}
192+
193+
/**
194+
* Builds and serializes a production log entry without ever throwing.
195+
*
196+
* Caller-supplied arguments are merged in verbatim, so a cyclic reference, a
197+
* BigInt, or a throwing getter would otherwise raise inside the caller's code
198+
* path — losing the line and aborting whatever was being logged about. A
199+
* logger must never be able to break its caller.
200+
*/
201+
const serializeEntry = (base: Record<string, unknown>, args: unknown[]): string => {
202+
try {
203+
return JSON.stringify(mergeArgs({ ...base }, args))
204+
} catch {}
205+
206+
try {
207+
return JSON.stringify(mergeArgs({ ...base }, args), tolerantReplacer())
208+
} catch {}
209+
210+
return minimalEntry(base)
211+
}
212+
213+
/**
214+
* Last-resort entry built only from fields this module controls.
215+
*
216+
* A replacer cannot rescue a throwing `toJSON`, because `JSON.stringify` invokes
217+
* it before the replacer ever sees the value. So the final fallback drops every
218+
* caller-supplied value instead of re-serializing it, and passes strings through
219+
* only when they are already strings — coercing would re-enter hostile
220+
* `toString`. What remains cannot throw.
221+
*/
222+
const minimalEntry = (base: Record<string, unknown>): string => {
223+
const asString = (value: unknown) => (typeof value === 'string' ? value : '[Unserializable]')
224+
return JSON.stringify({
225+
timestamp: asString(base.timestamp),
226+
level: asString(base.level),
227+
module: asString(base.module),
228+
message: asString(base.message),
229+
serializationError: true,
230+
})
231+
}
232+
233+
/**
234+
* Copies caller-supplied metadata into a plain object without ever throwing.
235+
*
236+
* `LoggerMetadata` is structurally typed, so nothing stops a caller from handing
237+
* over an object carrying a throwing getter or a hostile proxy. A spread invokes
238+
* those traps, so the copy degrades key-by-key and finally to a marker rather
239+
* than raising inside the caller's code path.
240+
*/
241+
const materializeMetadata = (metadata: LoggerMetadata): LoggerMetadata => {
242+
try {
243+
return { ...metadata }
244+
} catch {}
245+
246+
const safe: LoggerMetadata = {}
247+
try {
248+
for (const key of Object.keys(metadata)) {
249+
try {
250+
safe[key] = metadata[key]
251+
} catch {
252+
safe[key] = '[Unreadable]'
253+
}
254+
}
255+
return safe
256+
} catch {}
257+
258+
return { metadataError: true }
259+
}
260+
157261
/**
158262
* Logger class for standardized console logging
159263
*
@@ -206,7 +310,7 @@ export class Logger {
206310
child.module = this.module
207311
child.config = this.config
208312
child.isDev = this.isDev
209-
child.metadata = { ...this.metadata, ...metadata }
313+
child.metadata = { ...this.metadata, ...materializeMetadata(metadata) }
210314
return child
211315
}
212316

@@ -292,33 +396,17 @@ export class Logger {
292396
}
293397
} else {
294398
// Structured JSON for production — CloudWatch Log Insights auto-parses JSON lines
295-
const entry: Record<string, unknown> = {
399+
const base: Record<string, unknown> = {
296400
timestamp,
297401
level,
298402
module: this.module,
299403
message,
300404
}
301405
for (const [k, v] of metadataEntries) {
302-
entry[k] = v
303-
}
304-
// Merge extra args into the entry
305-
for (const arg of args) {
306-
if (
307-
arg !== null &&
308-
arg !== undefined &&
309-
typeof arg === 'object' &&
310-
!(arg instanceof Error)
311-
) {
312-
Object.assign(entry, arg)
313-
} else if (arg instanceof Error) {
314-
entry.error = arg.message
315-
entry.stack = arg.stack
316-
} else if (arg !== null && arg !== undefined) {
317-
entry.extra = arg
318-
}
406+
base[k] = v
319407
}
320408

321-
const line = JSON.stringify(entry)
409+
const line = serializeEntry(base, args)
322410
if (level === LogLevel.ERROR) {
323411
console.error(line)
324412
} else {

0 commit comments

Comments
 (0)