diff --git a/.changeset/add-sync-logger-child.md b/.changeset/add-sync-logger-child.md new file mode 100644 index 0000000..173bf47 --- /dev/null +++ b/.changeset/add-sync-logger-child.md @@ -0,0 +1,5 @@ +--- +"ff-serv": minor +--- + +Add `.child()` to sync logger for contextual annotations diff --git a/packages/serv/src/index.ts b/packages/serv/src/index.ts index 7db3d41..779dd6a 100644 --- a/packages/serv/src/index.ts +++ b/packages/serv/src/index.ts @@ -1,3 +1,4 @@ export * from './http/index.js'; +export type { SyncLogger } from './logger.js'; export { Logger } from './logger.js'; export { getPort } from './port.js'; diff --git a/packages/serv/src/logger.test.ts b/packages/serv/src/logger.test.ts new file mode 100644 index 0000000..7a58dda --- /dev/null +++ b/packages/serv/src/logger.test.ts @@ -0,0 +1,168 @@ +import { it } from '@effect/vitest'; +import { + Effect, + Array as EffectArray, + Logger as EffectLogger, + Layer, + LogLevel, +} from 'effect'; +import { describe, expect } from 'vitest'; +import { Logger } from './logger.js'; + +type CapturedEntry = { + message: string; + logLevel: LogLevel.LogLevel; + annotations: Record; +}; + +function makeTestLogger() { + const entries: Array = []; + + const logger = EffectLogger.make((options) => { + const annotations: Record = {}; + for (const [key, value] of options.annotations) { + annotations[key] = value; + } + entries.push({ + message: EffectArray.ensure(options.message).join(' '), + logLevel: options.logLevel, + annotations, + }); + }); + + const layer = Layer.merge( + EffectLogger.replace(EffectLogger.defaultLogger, logger), + EffectLogger.minimumLogLevel(LogLevel.All), + ); + + return { entries, layer }; +} + +describe('Logger.sync', () => { + it.effect('logs without annotations', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync().pipe(Effect.provide(layer)); + log.info('hello'); + yield* Effect.yieldNow(); + expect(entries).toHaveLength(1); + expect(entries[0].message).toBe('hello'); + expect(entries[0].annotations).toEqual({}); + }), + ); + + it.effect('initial annotations from sync()', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync({ service: 'api' }).pipe( + Effect.provide(layer), + ); + log.info('started'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ service: 'api' }); + }), + ); + + it.effect('.child() adds annotations', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync().pipe(Effect.provide(layer)); + const child = log.child({ requestId: '123' }); + child.info('handled'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ requestId: '123' }); + }), + ); + + it.effect('.child() merges parent + child annotations', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync({ service: 'api' }).pipe( + Effect.provide(layer), + ); + const child = log.child({ requestId: '123' }); + child.info('handled'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ + service: 'api', + requestId: '123', + }); + }), + ); + + it.effect('.child() overrides parent on key conflict', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync({ env: 'dev' }).pipe( + Effect.provide(layer), + ); + const child = log.child({ env: 'prod' }); + child.info('test'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ env: 'prod' }); + }), + ); + + it.effect('chained .child().child() accumulates annotations', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync({ a: 1 }).pipe(Effect.provide(layer)); + const grandchild = log.child({ b: 2 }).child({ c: 3 }); + grandchild.info('deep'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ a: 1, b: 2, c: 3 }); + }), + ); + + it.effect('parent unaffected by child creation', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const parent = yield* Logger.sync({ service: 'api' }).pipe( + Effect.provide(layer), + ); + parent.child({ requestId: '123' }); + parent.info('still parent'); + yield* Effect.yieldNow(); + expect(entries[0].annotations).toEqual({ service: 'api' }); + }), + ); + + it.effect('all log levels work on child', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync().pipe(Effect.provide(layer)); + const child = log.child({ ctx: 'test' }); + child.info('i'); + child.debug('d'); + child.warn('w'); + child.error('e'); + yield* Effect.yieldNow(); + expect(entries).toHaveLength(4); + expect(entries[0].logLevel).toBe(LogLevel.Info); + expect(entries[1].logLevel).toBe(LogLevel.Debug); + expect(entries[2].logLevel).toBe(LogLevel.Warning); + expect(entries[3].logLevel).toBe(LogLevel.Error); + for (const entry of entries) { + expect(entry.annotations).toEqual({ ctx: 'test' }); + } + }), + ); + + it.effect('per-call attributes merge with persistent annotations', () => + Effect.gen(function* () { + const { entries, layer } = makeTestLogger(); + const log = yield* Logger.sync({ service: 'api' }).pipe( + Effect.provide(layer), + ); + const child = log.child({ requestId: '123' }); + child.info({ extra: 'val' }, 'with attrs'); + yield* Effect.yieldNow(); + expect(entries[0].message).toBe('with attrs'); + expect(entries[0].annotations).toEqual({ + service: 'api', + requestId: '123', + extra: 'val', + }); + }), + ); +}); diff --git a/packages/serv/src/logger.ts b/packages/serv/src/logger.ts index 9da6459..c25156a 100644 --- a/packages/serv/src/logger.ts +++ b/packages/serv/src/logger.ts @@ -9,27 +9,48 @@ function extractParams(...[obj, msg]: LogParams) { return { message: msg, attributes: obj as Record }; } +// biome-ignore lint/suspicious/noExplicitAny: log annotations are unstructured +type LogAnnotations = Record; + +export type SyncLogger = { + info: (...params: Parameters) => void; + debug: (...params: Parameters) => void; + warn: (...params: Parameters) => void; + error: (...params: Parameters) => void; + child: (annotations: LogAnnotations) => SyncLogger; +}; + +function makeSyncLogger( + runtime: Runtime.Runtime, + annotations: LogAnnotations, +): SyncLogger { + const run = (e: Effect.Effect) => { + const annotated = + Object.keys(annotations).length > 0 + ? e.pipe(Effect.annotateLogs(annotations)) + : e; + void Runtime.runPromise(runtime)(annotated); + }; + + return { + info: (...params: Parameters) => + run(Logger.info(...params)), + debug: (...params: Parameters) => + run(Logger.debug(...params)), + warn: (...params: Parameters) => + run(Logger.warn(...params)), + error: (...params: Parameters) => + run(Logger.error(...params)), + child: (childAnnotations: LogAnnotations) => + makeSyncLogger(runtime, { ...annotations, ...childAnnotations }), + }; +} + export namespace Logger { - export const sync = () => + export const sync = (annotations?: LogAnnotations) => Effect.gen(function* () { const runtime = yield* Effect.runtime(); - - const run = (e: Effect.Effect) => { - // Intentionally ignoring the await here - // void runPromise(e); - void Runtime.runPromise(runtime)(e); - }; - - return { - info: (...params: Parameters) => - run(Logger.info(...params)), - debug: (...params: Parameters) => - run(Logger.debug(...params)), - warn: (...params: Parameters) => - run(Logger.warn(...params)), - error: (...params: Parameters) => - run(Logger.error(...params)), - }; + return makeSyncLogger(runtime, annotations ?? {}); }); // --