diff --git a/lib/hellog.ts b/lib/hellog.ts index c5a78ac..65b04a9 100644 --- a/lib/hellog.ts +++ b/lib/hellog.ts @@ -1,6 +1,7 @@ import { format } from 'node:util'; import { serializeError } from './errors.js'; import { HellogLevel, HellogLevelOrder } from './levels.js'; +import { HellogMeta, MetaInput } from './meta.js'; import { HellogMessage } from './messages.js'; import { HellogColorizeDefaultPlugin, @@ -9,11 +10,12 @@ import { HellogPrettyDefaultPlugin, HellogStdoutDefaultPlugin, } from './plugins.js'; +import { HellogTimer } from './timer.js'; interface HellogOptions { level?: HellogLevel; plugins?: HellogPlugin[]; - meta?: Record | (() => Record); + meta?: MetaInput; } /** @@ -63,7 +65,7 @@ export class Hellog { } readonly options: HellogOptions | undefined; - private readonly _timers = new Map(); + private readonly _timers = new HellogTimer(); constructor(options?: HellogOptions) { this.options = options; @@ -108,14 +110,11 @@ export class Hellog { * reqLog.info('handling request'); // includes requestId in meta * ``` */ - child(meta: Record | (() => Record)): Hellog { - const parentMeta = this.options?.meta; + child(meta: MetaInput): Hellog { + const childMeta = new HellogMeta(this.options?.meta).child(meta); return new Hellog({ ...this.options, - meta: () => ({ - ...Hellog._resolveMeta(parentMeta), - ...Hellog._resolveMeta(meta), - }), + meta: () => childMeta.resolve(), }); } @@ -124,7 +123,7 @@ export class Hellog { * Uses `process.hrtime.bigint()` for sub-millisecond monotonic precision. */ time(label: string): void { - this._timers.set(label, process.hrtime.bigint()); + this._timers.start(label); } /** @@ -135,28 +134,15 @@ export class Hellog { * @param level - The log level to use (default: DEBUG). */ timeEnd(label: string, level: HellogLevel = HellogLevel.DEBUG): void { - const start = this._timers.get(label); - if (start === undefined) return; - this._timers.delete(label); - const ms = Number(process.hrtime.bigint() - start) / 1_000_000; - this._log([`${label}: ${ms.toFixed(3)}ms`], level, { durationMs: ms }); - } - - private static _resolveMeta( - meta: Record | (() => Record) | undefined, - ): Record { - if (!meta) return {}; - if (typeof meta === 'function') return meta(); - return meta; + const ms = this._timers.end(label); + if (ms === undefined) return; + this._log([HellogTimer.format(label, ms)], level, { durationMs: ms }); } private _log(data: unknown[], level: HellogLevel, extraMeta?: Record): void { if (HellogLevelOrder[level] < HellogLevelOrder[this.maxLevel]) return; - const metaObject: Record = { - ...Hellog._resolveMeta(this.options?.meta), - ...extraMeta, - }; + const metaObject = new HellogMeta(this.options?.meta).merge(extraMeta); const err = data.find((d): d is Error => d instanceof Error); const serialized = serializeError(err); diff --git a/lib/index.ts b/lib/index.ts index cd9b250..a2d0f9e 100644 --- a/lib/index.ts +++ b/lib/index.ts @@ -2,4 +2,6 @@ export * from './errors.js'; export * from './hellog.js'; export * from './levels.js'; export * from './messages.js'; +export * from './meta.js'; export * from './plugins.js'; +export * from './timer.js'; diff --git a/lib/meta.spec.ts b/lib/meta.spec.ts new file mode 100644 index 0000000..4b9111d --- /dev/null +++ b/lib/meta.spec.ts @@ -0,0 +1,58 @@ +import assert from 'node:assert'; +import { describe, it } from 'node:test'; +import { HellogMeta } from './meta.js'; + +describe(HellogMeta.name, () => { + it('should resolve undefined source to an empty object', () => { + assert.deepStrictEqual(new HellogMeta(undefined).resolve(), {}); + }); + + it('should resolve a static object source', () => { + assert.deepStrictEqual(new HellogMeta({ service: 'api' }).resolve(), { service: 'api' }); + }); + + it('should resolve a factory source freshly on every call', () => { + let counter = 0; + const meta = new HellogMeta(() => ({ seq: ++counter })); + assert.deepStrictEqual(meta.resolve(), { seq: 1 }); + assert.deepStrictEqual(meta.resolve(), { seq: 2 }); + }); + + it('should merge extra meta on top of the base, extra winning', () => { + const meta = new HellogMeta({ service: 'api', env: 'prod' }); + assert.deepStrictEqual(meta.merge({ env: 'staging', requestId: '1' }), { + service: 'api', + env: 'staging', + requestId: '1', + }); + }); + + it('should merge with undefined extra unchanged', () => { + assert.deepStrictEqual(new HellogMeta({ service: 'api' }).merge(undefined), { service: 'api' }); + }); + + it('should layer child meta over parent, child winning', () => { + const parent = new HellogMeta({ service: 'api', env: 'prod' }); + const child = parent.child({ env: 'staging', requestId: '1' }); + assert.deepStrictEqual(child.resolve(), { + service: 'api', + env: 'staging', + requestId: '1', + }); + }); + + it('should re-evaluate dynamic parent and child sources lazily', () => { + let parentSeq = 0; + let childSeq = 0; + const parent = new HellogMeta(() => ({ parentSeq: ++parentSeq })); + const child = parent.child(() => ({ childSeq: ++childSeq })); + assert.deepStrictEqual(child.resolve(), { parentSeq: 1, childSeq: 1 }); + assert.deepStrictEqual(child.resolve(), { parentSeq: 2, childSeq: 2 }); + }); + + it('should nest children arbitrarily', () => { + const root = new HellogMeta({ a: 1 }); + const nested = root.child({ b: 2 }).child({ c: 3 }); + assert.deepStrictEqual(nested.resolve(), { a: 1, b: 2, c: 3 }); + }); +}); diff --git a/lib/meta.ts b/lib/meta.ts new file mode 100644 index 0000000..131f6fe --- /dev/null +++ b/lib/meta.ts @@ -0,0 +1,42 @@ +/** + * Static meta or a factory resolved fresh on every log call. + */ +export type MetaInput = Record | (() => Record); + +/** + * Owns meta resolution and parent/child merging. + * + * A factory source is re-evaluated on every {@link resolve}, so dynamic meta + * (e.g. a request id read from async-local storage) stays current. + */ +export class HellogMeta { + private readonly source: MetaInput | undefined; + + constructor(source: MetaInput | undefined) { + this.source = source; + } + + /** + * Resolve the source to a plain object. Returns `{}` when unset. + */ + resolve(): Record { + if (!this.source) return {}; + return typeof this.source === 'function' ? this.source() : this.source; + } + + /** + * Merge per-call extra meta on top of the resolved base meta. Extra keys win. + */ + merge(extra: Record | undefined): Record { + return { ...this.resolve(), ...extra }; + } + + /** + * Derive a child meta that layers `extra` over this one. Resolution stays + * lazy: both this meta and `extra` are re-resolved each time the child is + * resolved, and child keys win over parent keys. + */ + child(extra: MetaInput): HellogMeta { + return new HellogMeta(() => ({ ...this.resolve(), ...new HellogMeta(extra).resolve() })); + } +} diff --git a/lib/timer.spec.ts b/lib/timer.spec.ts new file mode 100644 index 0000000..2aefb17 --- /dev/null +++ b/lib/timer.spec.ts @@ -0,0 +1,38 @@ +import assert from 'node:assert'; +import { describe, it } from 'node:test'; +import { HellogTimer } from './timer.js'; + +describe(HellogTimer.name, () => { + it('should return a non-negative elapsed time for a started timer', () => { + const timer = new HellogTimer(); + timer.start('req'); + const ms = timer.end('req'); + assert.strictEqual(typeof ms, 'number'); + assert.ok((ms as number) >= 0); + }); + + it('should return undefined when ending an unknown label', () => { + const timer = new HellogTimer(); + assert.strictEqual(timer.end('never-started'), undefined); + }); + + it('should only allow a timer to be ended once', () => { + const timer = new HellogTimer(); + timer.start('req'); + assert.strictEqual(typeof timer.end('req'), 'number'); + assert.strictEqual(timer.end('req'), undefined); + }); + + it('should track multiple labels independently', () => { + const timer = new HellogTimer(); + timer.start('a'); + timer.start('b'); + assert.strictEqual(typeof timer.end('a'), 'number'); + assert.strictEqual(typeof timer.end('b'), 'number'); + }); + + it('should serialize a duration into the log message form', () => { + assert.strictEqual(HellogTimer.format('req', 12.3456), 'req: 12.346ms'); + assert.strictEqual(HellogTimer.format('boot', 0), 'boot: 0.000ms'); + }); +}); diff --git a/lib/timer.ts b/lib/timer.ts new file mode 100644 index 0000000..68a9579 --- /dev/null +++ b/lib/timer.ts @@ -0,0 +1,35 @@ +/** + * Owns named duration timers and their serialization. + * + * Uses `process.hrtime.bigint()` for sub-millisecond monotonic precision. + */ +export class HellogTimer { + private readonly _timers = new Map(); + + /** + * Start a timer for the given label. Call {@link end} to stop it. + */ + start(label: string): void { + this._timers.set(label, process.hrtime.bigint()); + } + + /** + * Stop a timer started with {@link start} and return the elapsed time in + * milliseconds, or `undefined` if the label was never started. A timer can + * only be ended once. + */ + end(label: string): number | undefined { + const start = this._timers.get(label); + if (start === undefined) return undefined; + this._timers.delete(label); + return Number(process.hrtime.bigint() - start) / 1_000_000; + } + + /** + * Serialize an elapsed duration into the log message form, e.g. + * `"request: 12.345ms"`. + */ + static format(label: string, ms: number): string { + return `${label}: ${ms.toFixed(3)}ms`; + } +}