diff --git a/CHANGES.md b/CHANGES.md index 20ad800..1338f1a 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -8,6 +8,13 @@ Version 0.5.0 To be released. + - LogTape now provides contexts for loggers. [[#7], [#8]] + + - Added `Logger.with()` method. + +[#7]: https://github.com/dahlia/logtape/issues/7 +[#8]: https://github.com/dahlia/logtape/pull/8 + Version 0.4.2 ------------- @@ -149,3 +156,5 @@ Version 0.1.0 ------------- Initial release. Released on April 19, 2024. + + diff --git a/README.md b/README.md index e37653d..21f559d 100644 --- a/README.md +++ b/README.md @@ -182,6 +182,36 @@ await configure({ ~~~~ +Contexts +-------- + +**Contexts are available since LogTape 0.5.0.** + +LogTape provides a context system to reuse the same properties across log +messages. A context is a key-value map. You can set a context for a logger +and log messages with the context. Here's an example of setting a context +for a logger: + +~~~~ typescript +const logger = getLogger(["my-app", "my-module"]); +const ctx = logger.with({ userId: 1234, requestId: "abc" }); +ctx.info `This log message will have the context (userId & requestId).`; +ctx.warn("Context can be used inside message template: {userId}, {requestId}."); +~~~~ + +The context is inherited by child loggers. Here's an example of setting a +context for a parent logger and logging messages with a child logger: + +~~~~ typescript +const logger = getLogger(["my-app"]); +const parentCtx = logger.with({ userId: 1234, requestId: "abc" }); +const childCtx = parentCtx.getLogger(["my-module"]); +childCtx.debug("This log message will have the context: {userId} {requestId}."); +~~~~ + +Contexts are particularly useful when you want to do structured logging. + + Sinks ----- diff --git a/logtape/logger.test.ts b/logtape/logger.test.ts index 4c80a55..82007a0 100644 --- a/logtape/logger.test.ts +++ b/logtape/logger.test.ts @@ -8,6 +8,7 @@ import { toFilter } from "./filter.ts"; import { debug, error, info, warning } from "./fixtures.ts"; import { getLogger, + LoggerCtx, LoggerImpl, parseMessageTemplate, renderMessage, @@ -42,6 +43,23 @@ Deno.test("Logger.getChild()", () => { const fooBarBaz = foo.getChild(["bar", "baz"]); assertEquals(fooBarBaz.category, ["foo", "bar", "baz"]); assertEquals(fooBarBaz.parent, fooBar); + + const fooCtx = foo.with({ a: 1, b: 2 }); + const fooBarCtx = fooCtx.getChild("bar"); + assertEquals(fooBarCtx.category, ["foo", "bar"]); + // @ts-ignore: internal attribute: + assertEquals(fooBarCtx.properties, { a: 1, b: 2 }); +}); + +Deno.test("Logger.with()", () => { + const foo = getLogger("foo"); + const ctx = foo.with({ a: 1, b: 2 }); + assertEquals(ctx.parent, getLogger()); + assertEquals(ctx.category, ["foo"]); + // @ts-ignore: internal attribute: + assertEquals(ctx.properties, { a: 1, b: 2 }); + // @ts-ignore: internal attribute: + assertEquals(ctx.with({ c: 3 }).properties, { a: 1, b: 2, c: 3 }); }); Deno.test("LoggerImpl.filter()", async (t) => { @@ -303,10 +321,136 @@ Deno.test("LoggerImpl.logTemplate()", async (t) => { }); }); +Deno.test("LoggerCtx.log()", async (t) => { + const logger = LoggerImpl.getLogger("foo"); + const ctx = new LoggerCtx(logger, { a: 1, b: 2 }); + + await t.step("test", () => { + const logs: LogRecord[] = []; + logger.sinks.push(logs.push.bind(logs)); + const before = Date.now(); + ctx.log("info", "Hello, {a} {b} {c}!", { c: 3 }); + const after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: "info", + message: ["Hello, ", 1, " ", 2, " ", 3, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2, c: 3 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); + + logs.shift(); + logger.filters.push(toFilter("error")); + let called = 0; + ctx.log("warning", "Hello, {a} {b} {c}!", () => { + called++; + return { c: 3 }; + }); + assertEquals(logs, []); + assertEquals(called, 0); + + ctx.log("error", "Hello, {a} {b} {c}!", () => { + called++; + return { c: 3 }; + }); + assertEquals(logs, [ + { + category: ["foo"], + level: "error", + message: ["Hello, ", 1, " ", 2, " ", 3, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2, c: 3 }, + }, + ]); + assertEquals(called, 1); + }); + + await t.step("tear down", () => { + logger.resetDescendants(); + }); +}); + +Deno.test("LoggerCtx.logLazily()", async (t) => { + const logger = LoggerImpl.getLogger("foo"); + const ctx = new LoggerCtx(logger, { a: 1, b: 2 }); + + await t.step("test", () => { + let called = 0; + function calc() { + called++; + return 123; + } + + const logs: LogRecord[] = []; + logger.sinks.push(logs.push.bind(logs)); + logger.filters.push(toFilter("error")); + logger.logLazily("warning", (l) => l`Hello, ${calc()}!`); + assertEquals(logs, []); + assertEquals(called, 0); + + const before = Date.now(); + ctx.logLazily("error", (l) => l`Hello, ${calc()}!`); + const after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: "error", + message: ["Hello, ", 123, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); + assertEquals(called, 1); + }); + + await t.step("tear down", () => { + logger.resetDescendants(); + }); +}); + +Deno.test("LoggerCtx.logTemplate()", async (t) => { + const logger = LoggerImpl.getLogger("foo"); + const ctx = new LoggerCtx(logger, { a: 1, b: 2 }); + + await t.step("test", () => { + function info(tpl: TemplateStringsArray, ...values: unknown[]) { + ctx.logTemplate("info", tpl, values); + } + const logs: LogRecord[] = []; + logger.sinks.push(logs.push.bind(logs)); + + const before = Date.now(); + info`Hello, ${123}!`; + const after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: "info", + message: ["Hello, ", 123, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); + }); + + await t.step("tear down", () => { + logger.resetDescendants(); + }); +}); + const methods = ["debug", "info", "warn", "error", "fatal"] as const; for (const method of methods) { Deno.test(`Logger.${method}()`, async (t) => { const logger = LoggerImpl.getLogger("foo"); + const ctx = new LoggerCtx(logger, { a: 1, b: 2 }); await t.step("template", () => { function tpl(tpl: TemplateStringsArray, ...values: unknown[]) { @@ -315,9 +459,9 @@ for (const method of methods) { const logs: LogRecord[] = []; logger.sinks.push(logs.push.bind(logs)); - const before = Date.now(); + let before = Date.now(); tpl`Hello, ${123}!`; - const after = Date.now(); + let after = Date.now(); assertEquals(logs, [ { category: ["foo"], @@ -329,6 +473,26 @@ for (const method of methods) { ]); assertGreaterOrEqual(logs[0].timestamp, before); assertLessOrEqual(logs[0].timestamp, after); + + function ctxTpl(tpl: TemplateStringsArray, ...values: unknown[]) { + ctx[method](tpl, ...values); + } + + logs.shift(); + before = Date.now(); + ctxTpl`Hello, ${123}!`; + after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: method === "warn" ? "warning" : method, + message: ["Hello, ", 123, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); }); await t.step("tear down", () => { @@ -338,9 +502,9 @@ for (const method of methods) { await t.step("lazy template", () => { const logs: LogRecord[] = []; logger.sinks.push(logs.push.bind(logs)); - const before = Date.now(); + let before = Date.now(); logger[method]((l) => l`Hello, ${123}!`); - const after = Date.now(); + let after = Date.now(); assertEquals(logs, [ { category: ["foo"], @@ -352,6 +516,22 @@ for (const method of methods) { ]); assertGreaterOrEqual(logs[0].timestamp, before); assertLessOrEqual(logs[0].timestamp, after); + + logs.shift(); + before = Date.now(); + ctx[method]((l) => l`Hello, ${123}!`); + after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: method === "warn" ? "warning" : method, + message: ["Hello, ", 123, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); }); await t.step("tear down", () => { @@ -361,9 +541,9 @@ for (const method of methods) { await t.step("eager", () => { const logs: LogRecord[] = []; logger.sinks.push(logs.push.bind(logs)); - const before = Date.now(); + let before = Date.now(); logger[method]("Hello, {foo}!", { foo: 123 }); - const after = Date.now(); + let after = Date.now(); assertEquals(logs, [ { category: ["foo"], @@ -387,6 +567,32 @@ for (const method of methods) { properties: {}, }, ]); + + logs.shift(); + before = Date.now(); + ctx[method]("Hello, {a} {b} {c}!", { c: 3 }); + after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: method === "warn" ? "warning" : method, + message: ["Hello, ", 1, " ", 2, " ", 3, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2, c: 3 }, + }, + ]); + + logs.shift(); + ctx[method]("Hello, world!"); + assertEquals(logs, [ + { + category: ["foo"], + level: method === "warn" ? "warning" : method, + message: ["Hello, world!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2 }, + }, + ]); }); await t.step("tear down", () => { @@ -396,12 +602,11 @@ for (const method of methods) { await t.step("lazy", () => { const logs: LogRecord[] = []; logger.sinks.push(logs.push.bind(logs)); - const before = Date.now(); - + let before = Date.now(); logger[method]("Hello, {foo}!", () => { return { foo: 123 }; }); - const after = Date.now(); + let after = Date.now(); assertEquals(logs, [ { category: ["foo"], @@ -413,6 +618,24 @@ for (const method of methods) { ]); assertGreaterOrEqual(logs[0].timestamp, before); assertLessOrEqual(logs[0].timestamp, after); + + logs.shift(); + before = Date.now(); + ctx[method]("Hello, {a} {b} {c}!", () => { + return { c: 3 }; + }); + after = Date.now(); + assertEquals(logs, [ + { + category: ["foo"], + level: method === "warn" ? "warning" : method, + message: ["Hello, ", 1, " ", 2, " ", 3, "!"], + timestamp: logs[0].timestamp, + properties: { a: 1, b: 2, c: 3 }, + }, + ]); + assertGreaterOrEqual(logs[0].timestamp, before); + assertLessOrEqual(logs[0].timestamp, after); }); await t.step("tear down", () => { diff --git a/logtape/logger.ts b/logtape/logger.ts index a6545f9..c1bf6e1 100644 --- a/logtape/logger.ts +++ b/logtape/logger.ts @@ -50,6 +50,34 @@ export interface Logger { subcategory: string | readonly [string] | readonly [string, ...string[]], ): Logger; + /** + * Get a logger with contextual properties. This is useful for + * log multiple messages with the shared set of properties. + * + * ```typescript + * const logger = getLogger("category"); + * const ctx = logger.with({ foo: 123, bar: "abc" }); + * ctx.info("A message with {foo} and {bar}."); + * ctx.warn("Another message with {foo}, {bar}, and {baz}.", { baz: true }); + * ``` + * + * The above code is equivalent to: + * + * ```typescript + * const logger = getLogger("category"); + * logger.info("A message with {foo} and {bar}.", { foo: 123, bar: "abc" }); + * logger.warn( + * "Another message with {foo}, {bar}, and {baz}.", + * { foo: 123, bar: "abc", baz: true }, + * ); + * ``` + * + * @param properties + * @returns + * @since 0.5.0 + */ + with(properties: Record): Logger; + /** * Log a debug message. Use this as a template string prefix. * @@ -446,6 +474,10 @@ export class LoggerImpl implements Logger { this.reset(); } + with(properties: Record): Logger { + return new LoggerCtx(this, { ...properties }); + } + filter(record: LogRecord): boolean { for (const filter of this.filters) { if (!filter(record)) return false; @@ -513,6 +545,7 @@ export class LoggerImpl implements Logger { logLazily( level: LogLevel, callback: LogCallback, + properties: Record = {}, ): void { let msg: unknown[] | undefined = undefined; this.emit({ @@ -525,7 +558,7 @@ export class LoggerImpl implements Logger { return msg; }, timestamp: Date.now(), - properties: {}, + properties, }); } @@ -533,13 +566,14 @@ export class LoggerImpl implements Logger { level: LogLevel, messageTemplate: TemplateStringsArray, values: unknown[], + properties: Record = {}, ): void { this.emit({ category: this.category, level, message: renderMessage(messageTemplate, values), timestamp: Date.now(), - properties: {}, + properties, }); } @@ -613,6 +647,139 @@ export class LoggerImpl implements Logger { } } +/** + * A logger implementation with contextual properties. Do not use this + * directly; use {@link Logger.with} instead. This class is exported + * for testing purposes. + */ +export class LoggerCtx implements Logger { + logger: LoggerImpl; + properties: Record; + + constructor(logger: LoggerImpl, properties: Record) { + this.logger = logger; + this.properties = properties; + } + + get category(): readonly string[] { + return this.logger.category; + } + + get parent(): Logger | null { + return this.logger.parent; + } + + getChild( + subcategory: string | readonly [string] | readonly [string, ...string[]], + ): Logger { + return this.logger.getChild(subcategory).with(this.properties); + } + + with(properties: Record): Logger { + return new LoggerCtx(this.logger, { ...this.properties, ...properties }); + } + + log( + level: LogLevel, + message: string, + properties: Record | (() => Record), + bypassSinks?: Set, + ): void { + this.logger.log( + level, + message, + typeof properties === "function" + ? () => ({ + ...this.properties, + ...properties(), + }) + : { ...this.properties, ...properties }, + bypassSinks, + ); + } + + logLazily(level: LogLevel, callback: LogCallback): void { + this.logger.logLazily(level, callback, this.properties); + } + + logTemplate( + level: LogLevel, + messageTemplate: TemplateStringsArray, + values: unknown[], + ): void { + this.logger.logTemplate(level, messageTemplate, values, this.properties); + } + + debug( + message: TemplateStringsArray | string | LogCallback, + ...values: unknown[] + ): void { + if (typeof message === "string") { + this.log("debug", message, (values[0] ?? {}) as Record); + } else if (typeof message === "function") { + this.logLazily("debug", message); + } else { + this.logTemplate("debug", message, values); + } + } + + info( + message: TemplateStringsArray | string | LogCallback, + ...values: unknown[] + ): void { + if (typeof message === "string") { + this.log("info", message, (values[0] ?? {}) as Record); + } else if (typeof message === "function") { + this.logLazily("info", message); + } else { + this.logTemplate("info", message, values); + } + } + + warn( + message: TemplateStringsArray | string | LogCallback, + ...values: unknown[] + ): void { + if (typeof message === "string") { + this.log( + "warning", + message, + (values[0] ?? {}) as Record, + ); + } else if (typeof message === "function") { + this.logLazily("warning", message); + } else { + this.logTemplate("warning", message, values); + } + } + + error( + message: TemplateStringsArray | string | LogCallback, + ...values: unknown[] + ): void { + if (typeof message === "string") { + this.log("error", message, (values[0] ?? {}) as Record); + } else if (typeof message === "function") { + this.logLazily("error", message); + } else { + this.logTemplate("error", message, values); + } + } + + fatal( + message: TemplateStringsArray | string | LogCallback, + ...values: unknown[] + ): void { + if (typeof message === "string") { + this.log("fatal", message, (values[0] ?? {}) as Record); + } else if (typeof message === "function") { + this.logLazily("fatal", message); + } else { + this.logTemplate("fatal", message, values); + } + } +} + /** * The meta logger. It is a logger with the category `["logtape", "meta"]`. */