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
38 changes: 12 additions & 26 deletions lib/hellog.ts
Original file line number Diff line number Diff line change
@@ -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,
Expand All @@ -9,11 +10,12 @@ import {
HellogPrettyDefaultPlugin,
HellogStdoutDefaultPlugin,
} from './plugins.js';
import { HellogTimer } from './timer.js';

interface HellogOptions {
level?: HellogLevel;
plugins?: HellogPlugin[];
meta?: Record<string, unknown> | (() => Record<string, unknown>);
meta?: MetaInput;
}

/**
Expand Down Expand Up @@ -63,7 +65,7 @@ export class Hellog {
}

readonly options: HellogOptions | undefined;
private readonly _timers = new Map<string, bigint>();
private readonly _timers = new HellogTimer();

constructor(options?: HellogOptions) {
this.options = options;
Expand Down Expand Up @@ -108,14 +110,11 @@ export class Hellog {
* reqLog.info('handling request'); // includes requestId in meta
* ```
*/
child(meta: Record<string, unknown> | (() => Record<string, unknown>)): 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(),
});
}

Expand All @@ -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);
}

/**
Expand All @@ -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<string, unknown> | (() => Record<string, unknown>) | undefined,
): Record<string, unknown> {
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<string, unknown>): void {
if (HellogLevelOrder[level] < HellogLevelOrder[this.maxLevel]) return;

const metaObject: Record<string, unknown> = {
...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);
Expand Down
2 changes: 2 additions & 0 deletions lib/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
58 changes: 58 additions & 0 deletions lib/meta.spec.ts
Original file line number Diff line number Diff line change
@@ -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 });
});
});
42 changes: 42 additions & 0 deletions lib/meta.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
/**
* Static meta or a factory resolved fresh on every log call.
*/
export type MetaInput = Record<string, unknown> | (() => Record<string, unknown>);

/**
* 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<string, unknown> {
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<string, unknown> | undefined): Record<string, unknown> {
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() }));
}
}
38 changes: 38 additions & 0 deletions lib/timer.spec.ts
Original file line number Diff line number Diff line change
@@ -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');
});
});
35 changes: 35 additions & 0 deletions lib/timer.ts
Original file line number Diff line number Diff line change
@@ -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<string, bigint>();

/**
* 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`;
}
}
Loading