Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
127 changes: 127 additions & 0 deletions packages/logger/src/index.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<string, unknown> = { 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<Logger['withMetadata']>[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<string, unknown> = { 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<Logger['withMetadata']>[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<Logger['withMetadata']>[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)
})
})
})
128 changes: 108 additions & 20 deletions packages/logger/src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -139,6 +139,110 @@ const formatObject = (obj: unknown, isDev: boolean): string => {
}
}

/** Merges caller-supplied log arguments into the structured entry. */
const mergeArgs = (entry: Record<string, unknown>, args: unknown[]): Record<string, unknown> => {
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<string, unknown>, 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, unknown>): 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
*
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -280,33 +384,17 @@ export class Logger {
}
} else {
// Structured JSON for production — CloudWatch Log Insights auto-parses JSON lines
const entry: Record<string, unknown> = {
const base: Record<string, unknown> = {
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)
Comment thread
waleedlatif1 marked this conversation as resolved.
if (level === LogLevel.ERROR) {
console.error(line)
} else {
Expand Down
Loading