diff --git a/.changeset/fuzzy-logger-context.md b/.changeset/fuzzy-logger-context.md new file mode 100644 index 00000000..407a07c3 --- /dev/null +++ b/.changeset/fuzzy-logger-context.md @@ -0,0 +1,5 @@ +--- +"@restatedev/restate-sdk": patch +--- + +Add `ctx.console.child(...)` for immutable, replay-aware logger context enrichment. diff --git a/packages/examples/node/package.json b/packages/examples/node/package.json index a5e98749..fba028c1 100644 --- a/packages/examples/node/package.json +++ b/packages/examples/node/package.json @@ -13,6 +13,7 @@ "greeter": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/greeter.ts", "greeter_hooks": "RESTATE_LOGGING=ERROR tsx --tsconfig ./tsconfig.json ./src/greeter_with_hooks.ts", "greeter_http1": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/greeter_http1.ts", + "logger_context": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/logger_context.ts", "preview_serde": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/preview_serde.ts", "zgreeter": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/zod_greeter.ts", "workflow": "RESTATE_LOGGING=debug tsx --tsconfig ./tsconfig.json ./src/workflow.ts", diff --git a/packages/examples/node/src/logger_context.ts b/packages/examples/node/src/logger_context.ts new file mode 100644 index 00000000..e4da8c9c --- /dev/null +++ b/packages/examples/node/src/logger_context.ts @@ -0,0 +1,71 @@ +import { service, serve, type Context } from "@restatedev/restate-sdk"; + +interface CheckoutRequest { + orderId: string; + customerId: string; + paymentMethodId: string; +} + +interface PaymentResult { + paymentId: string; +} + +const checkout = service({ + name: "checkout", + handlers: { + submit: async (ctx: Context, input: CheckoutRequest) => { + let contextLogger = ctx.console.child({ + orderId: input.orderId, + customerId: input.customerId, + }); + + contextLogger.info("checkout started"); + + const payment = await ctx.run("charge payment", async () => { + return await chargePayment(input); + }); + + // This is rebuilt on replay from the journaled ctx.run result. + contextLogger = contextLogger.child({ paymentId: payment.paymentId }); + contextLogger.info("payment charged"); + + const shipment = await ctx.run("create shipment", async () => { + return await createShipment(input.orderId); + }); + + contextLogger + .child({ shipmentId: shipment.shipmentId }) + .info("shipment created"); + + return { + orderId: input.orderId, + paymentId: payment.paymentId, + shipmentId: shipment.shipmentId, + }; + }, + }, +}); + +export type Checkout = typeof checkout; + +/** + * Simulates charging a payment provider and returns a durable payment id. + */ +async function chargePayment(input: CheckoutRequest): Promise { + return { + paymentId: `payment-${input.paymentMethodId}`, + }; +} + +/** + * Simulates creating a shipment and returns a durable shipment id. + */ +async function createShipment( + orderId: string +): Promise<{ shipmentId: string }> { + return { + shipmentId: `shipment-${orderId}`, + }; +} + +serve({ services: [checkout] }); diff --git a/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts b/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts new file mode 100644 index 00000000..0f67111c --- /dev/null +++ b/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts @@ -0,0 +1,402 @@ +/* + * Copyright (c) 2023-2026 - Restate Software, Inc., Restate GmbH + * + * This file is part of the Restate SDK for Node.js/TypeScript, + * which is released under the MIT license. + * + * You can find a copy of the license in file LICENSE in the root + * directory of this repository or package, or at + * https://github.com/restatedev/sdk-typescript/blob/main/LICENSE + */ + +import { describe, expect, test } from "vitest"; +import * as http2 from "node:http2"; +import type * as net from "node:net"; +import * as restate from "@restatedev/restate-sdk"; +import * as sdkClients from "@restatedev/restate-sdk-clients"; +import { RestateTestEnvironment } from "@restatedev/restate-sdk-testcontainers"; + +/** + * Waits for asynchronous Restate processing to advance in polling-based tests. + */ +const wait = (ms: number) => new Promise((r) => setTimeout(r, ms)); + +type LoggerContextWorkerRestartInput = { + orderId: string; + paymentId: string; +}; + +const retryStepCount = 5; + +type LoggerContextRetryInput = { + workflowId: string; +}; + +type RetryContext = Record; + +const retryAttempts = new Map(); + +const workerRestartMessages = new Set([ + "before-worker-restart", + "after-worker-restart", +]); + +/** + * Records and returns the next attempt number for a retrying durable step. + */ +function bumpRetryAttempt(workflowId: string, step: number): number { + const key = `${workflowId}:step-${step}`; + const attempt = (retryAttempts.get(key) ?? 0) + 1; + retryAttempts.set(key, attempt); + return attempt; +} + +const loggerContextWorkerRestart = restate.service({ + name: "loggerContextWorkerRestart", + handlers: { + run: async ( + ctx: restate.Context, + input: LoggerContextWorkerRestartInput + ): Promise => { + let log = ctx.console.child({ orderId: input.orderId }); + + const payment = await ctx.run("payment", () => ({ + paymentId: input.paymentId, + })); + log = log.child({ paymentId: payment.paymentId }); + + log.info("before-worker-restart"); + await ctx.sleep(2_000, "worker-restart"); + log.info("after-worker-restart"); + + return "done"; + }, + }, +}); + +const loggerContextRetry = restate.service({ + name: "loggerContextRetry", + handlers: { + run: async ( + ctx: restate.Context, + input: LoggerContextRetryInput + ): Promise => { + let log = ctx.console.child({ workflowId: input.workflowId }); + const context: RetryContext = { workflowId: input.workflowId }; + + for (let step = 1; step <= retryStepCount; step++) { + const fieldName = `step${step}`; + const fieldValue = `value-${step}`; + + const result = await ctx.run( + `step-${step}`, + () => { + const attempt = bumpRetryAttempt(input.workflowId, step); + if (attempt === 1) { + throw new Error(`step-${step} failed once`); + } + return { fieldName, fieldValue }; + }, + { maxRetryAttempts: 3, initialRetryInterval: 25 } + ); + + context[result.fieldName] = result.fieldValue; + log = log.child({ [result.fieldName]: result.fieldValue }); + log.info(`after-step-${step}`); + } + + return context; + }, + }, +}); + +type CapturedLogEvent = { + worker: string; + message: string; + replaying: boolean; + source: string; + additionalContext: Record; +}; + +/** + * Creates a logger transport that captures selected user log messages together + * with the worker label and copied logger context. + * + * By default it captures the worker restart service logs: + * `before-worker-restart` is emitted by worker 1 immediately before the + * invocation suspends on `ctx.sleep`, and `after-worker-restart` is emitted + * after Restate resumes the same invocation on worker 2. Tests that assert + * different log points pass their own message set. + */ +function captureLogger( + worker: string, + events: CapturedLogEvent[], + capturedMessages = workerRestartMessages +): restate.LoggerTransport { + return (meta, message) => { + if (!capturedMessages.has(String(message))) { + return; + } + + events.push({ + worker, + message: String(message), + replaying: meta.replaying, + source: String(meta.source), + additionalContext: { ...(meta.context?.additionalContext ?? {}) }, + }); + }; +} + +/** + * Polls until a captured log event matching the predicate is observed. + */ +async function waitForLogEvent( + events: CapturedLogEvent[], + predicate: (event: CapturedLogEvent) => boolean, + timeoutMs = 10_000 +): Promise { + const start = Date.now(); + while (Date.now() - start < timeoutMs) { + const event = events.find(predicate); + if (event) { + return event; + } + await wait(25); + } + + throw new Error( + `Timed out waiting for log event. Events: ${JSON.stringify(events)}` + ); +} + +/** + * Tracks active HTTP/2 sessions so worker shutdown can force lingering sessions + * closed when the server is intentionally restarted. + */ +function trackHttp2Sessions(server: http2.Http2Server): { + destroySessions: () => void; +} { + const sessions = new Set(); + server.on("session", (session) => { + sessions.add(session); + session.once("close", () => sessions.delete(session)); + }); + + return { + destroySessions() { + for (const session of sessions) { + if (!session.destroyed) { + session.destroy(); + } + } + }, + }; +} + +/** + * Closes an HTTP/2 server and optionally destroys tracked sessions if graceful + * shutdown stalls. + */ +async function closeHttp2Server( + server: http2.Http2Server, + tracker?: { destroySessions: () => void } +): Promise { + await new Promise((resolve, reject) => { + const forceClose = setTimeout(() => tracker?.destroySessions(), 250); + server.close((error?: Error) => { + clearTimeout(forceClose); + if ( + error && + (error as NodeJS.ErrnoException).code !== "ERR_SERVER_NOT_RUNNING" + ) { + reject(error); + return; + } + resolve(); + }); + }); +} + +/** + * Starts a replacement SDK worker on the same port as the original worker. + */ +async function startLoggerContextWorker( + port: number, + logger: restate.LoggerTransport +): Promise { + const handler = restate.createEndpointHandler({ + services: [loggerContextWorkerRestart], + logger, + }); + const server = http2.createServer(handler); + + await new Promise((resolve, reject) => { + server + .listen(port) + .once("listening", () => resolve()) + .once("error", reject); + }); + + return server; +} + +/** + * Builds the expected accumulated retry logger context up to the requested step. + */ +function expectedRetryContext(upToStep = retryStepCount): RetryContext { + const context: RetryContext = { + workflowId: "retry-context-workflow", + }; + + for (let step = 1; step <= upToStep; step++) { + context[`step${step}`] = `value-${step}`; + } + + return context; +} + +/** + * Returns the retry test log messages that should be captured by the transport. + */ +function retryLogMessages(): Set { + return new Set( + Array.from({ length: retryStepCount }, (_, index) => { + return `after-step-${index + 1}`; + }) + ); +} + +describe("logger context worker restart", () => { + test("rebuilds child logger context after worker restart", async () => { + const events: CapturedLogEvent[] = []; + let env: RestateTestEnvironment | undefined; + let originalTracker: ReturnType | undefined; + let replacementWorker: http2.Http2Server | undefined; + let replacementTracker: ReturnType | undefined; + + try { + env = await RestateTestEnvironment.start({ + services: [loggerContextWorkerRestart], + logger: captureLogger("worker-1", events), + }); + originalTracker = trackHttp2Sessions(env.startedRestateHttpServer); + const workerAddress = + env.startedRestateHttpServer.address() as net.AddressInfo; + const workerPort = workerAddress.port; + const rs = sdkClients.connect({ url: env.baseUrl() }); + const client = rs.serviceClient(loggerContextWorkerRestart); + const input = { + orderId: "order-worker-restart", + paymentId: "payment-worker-restart", + }; + + const result = client.run(input); + const worker1Before = await waitForLogEvent( + events, + (event) => + event.worker === "worker-1" && + event.message === "before-worker-restart" && + !event.replaying + ); + + expect(worker1Before.source).toBe("USER"); + expect(worker1Before.additionalContext).toStrictEqual(input); + + await wait(150); + await closeHttp2Server(env.startedRestateHttpServer, originalTracker); + + replacementWorker = await startLoggerContextWorker( + workerPort, + captureLogger("worker-2", events) + ); + replacementTracker = trackHttp2Sessions(replacementWorker); + + await expect(result).resolves.toBe("done"); + + const worker2Before = await waitForLogEvent( + events, + (event) => + event.worker === "worker-2" && + event.message === "before-worker-restart" && + event.replaying + ); + const worker2After = await waitForLogEvent( + events, + (event) => + event.worker === "worker-2" && + event.message === "after-worker-restart" && + !event.replaying + ); + + expect(worker2Before.source).toBe("USER"); + expect(worker2Before.additionalContext).toStrictEqual(input); + expect(worker2After.source).toBe("USER"); + expect(worker2After.additionalContext).toStrictEqual(input); + expect( + events.some( + (event) => + event.worker === "worker-1" && + event.message === "after-worker-restart" + ) + ).toBe(false); + } finally { + if (replacementWorker) { + await closeHttp2Server(replacementWorker, replacementTracker); + } + if (env) { + await closeHttp2Server(env.startedRestateHttpServer, originalTracker); + await env.startedRestateContainer.stop(); + } + } + }, 30_000); +}); + +describe("logger context retry recovery", () => { + test("emits each visible log once and keeps accumulated context after retries", async () => { + retryAttempts.clear(); + const events: CapturedLogEvent[] = []; + let env: RestateTestEnvironment | undefined; + + try { + env = await RestateTestEnvironment.start({ + services: [loggerContextRetry], + logger: captureLogger("worker", events, retryLogMessages()), + alwaysReplay: true, + }); + const rs = sdkClients.connect({ url: env.baseUrl() }); + const client = rs.serviceClient(loggerContextRetry); + + await expect( + client.run({ workflowId: "retry-context-workflow" }) + ).resolves.toStrictEqual(expectedRetryContext()); + + for (let step = 1; step <= retryStepCount; step++) { + expect(retryAttempts.get(`retry-context-workflow:step-${step}`)).toBe( + 2 + ); + } + + const visibleUserLogs = events.filter((event) => { + return event.source === "USER" && !event.replaying; + }); + + expect(visibleUserLogs.map((event) => event.message)).toStrictEqual([ + "after-step-1", + "after-step-2", + "after-step-3", + "after-step-4", + "after-step-5", + ]); + + for (let step = 1; step <= retryStepCount; step++) { + expect(visibleUserLogs[step - 1]?.additionalContext).toStrictEqual( + expectedRetryContext(step) + ); + } + } finally { + retryAttempts.clear(); + await env?.stop(); + } + }, 30_000); +}); diff --git a/packages/libs/restate-sdk/README.md b/packages/libs/restate-sdk/README.md index e83feaf1..932a59af 100644 --- a/packages/libs/restate-sdk/README.md +++ b/packages/libs/restate-sdk/README.md @@ -48,6 +48,38 @@ npx -y @restatedev/create-app@latest Check the [Quickstart](https://docs.restate.dev/get_started/quickstart) for more info. +## Logging with Context + +Use `ctx.console` for handler logs. It behaves like `console`, but Restate attaches invocation metadata and suppresses user logs while replaying already-journaled work. + +You can create child loggers to add fields that should appear on every later log line: + +```typescript +const checkout = restate.service({ + name: "checkout", + handlers: { + submit: async (ctx: restate.Context, input: CheckoutRequest) => { + let log = ctx.console.child({ orderId: input.orderId }); + + log.info("checkout started"); + + const payment = await ctx.run("charge payment", async () => { + return await chargePayment(input); + }); + + log = log.child({ paymentId: payment.paymentId }); + log.info("payment charged"); + + return "ok"; + }, + }, +}); +``` + +Child loggers are immutable: `log.child(...)` returns a new logger with merged fields, and later fields override earlier fields with the same key. The logger object itself is not persisted between workers, so build child loggers from durable values such as handler input, object/workflow keys, state, request metadata, and `ctx.run` results. Do not add logger context only inside a `ctx.run` closure, because replay skips closures whose results are already journaled. + +Custom logger transports receive these fields as `meta.context?.additionalContext`, so Winston, Pino, or any structured logger can include them in emitted records. + ## Versions This library follows [Semantic Versioning](https://semver.org/). diff --git a/packages/libs/restate-sdk/src/common_api.ts b/packages/libs/restate-sdk/src/common_api.ts index 58eba713..a30f84f7 100644 --- a/packages/libs/restate-sdk/src/common_api.ts +++ b/packages/libs/restate-sdk/src/common_api.ts @@ -28,6 +28,7 @@ export type { ContextDate, RunAction, RunOptions, + RestateConsole, KeyValueStore, DurablePromise, Request, diff --git a/packages/libs/restate-sdk/src/context.ts b/packages/libs/restate-sdk/src/context.ts index ccb46c62..5c6ad249 100644 --- a/packages/libs/restate-sdk/src/context.ts +++ b/packages/libs/restate-sdk/src/context.ts @@ -257,6 +257,44 @@ export type GenericSend = { name?: string; }; +/** + * Console to use for replay-aware logging. + * + * `RestateConsole` behaves like the standard `Console`, but Restate attaches + * invocation metadata and suppresses user logs while replaying already-journaled + * work. + */ +export type RestateConsole = Console & { + /** + * Creates a child console that attaches the provided contextual fields to each + * log event. + * Context values must be serializable. + * + * Child consoles are immutable: this method returns a new console and does not + * mutate the parent console. Nested children merge their fields, and later + * fields override earlier fields with the same name. + * + * The child console object itself is not persisted between workers. Rebuild it + * from durable values such as handler input, object/workflow keys, state, + * request metadata, and `ctx.run` results. Avoid adding logger context only + * inside a `ctx.run` closure, because replay skips closures whose results are + * already journaled. + * + * @example Progressively enrich log context + * ```ts + * let log = ctx.console.child({ orderId: input.orderId }); + * + * const payment = await ctx.run("charge payment", async () => { + * return await chargePayment(input); + * }); + * + * log = log.child({ paymentId: payment.paymentId }); + * log.info("payment charged"); + * ``` + */ + child(context: Record): RestateConsole; +}; + /** * The context that gives access to all Restate-backed operations, for example * - sending reliable messages / RPC through Restate @@ -282,9 +320,10 @@ export interface Context extends RestateContext { /** * Console to use for logging. It attaches to each log message some contextual information, - * such as invoked service method and invocation id, and automatically excludes logs during replay. + * such as invoked service method and invocation id, and automatically excludes user logs during replay. + * Use {@link RestateConsole.child} to add custom contextual fields to all logs emitted by a child logger. */ - console: Console; + console: RestateConsole; /** * Deterministic date. diff --git a/packages/libs/restate-sdk/src/context_impl.ts b/packages/libs/restate-sdk/src/context_impl.ts index 00f77291..f753ed48 100644 --- a/packages/libs/restate-sdk/src/context_impl.ts +++ b/packages/libs/restate-sdk/src/context_impl.ts @@ -22,6 +22,7 @@ import type { ObjectContext, Rand, Request, + RestateConsole, RestatePromise, RunAction, RunOptions, @@ -112,7 +113,7 @@ export class ContextImpl constructor( readonly coreVm: WasmVM, input: WasmInput, - public readonly console: Console, + public readonly console: RestateConsole, public readonly handlerKind: HandlerKind, readonly vmLogger: Console, private readonly invocationRequest: Request, diff --git a/packages/libs/restate-sdk/src/endpoint.ts b/packages/libs/restate-sdk/src/endpoint.ts index fa0dcc41..043531fe 100644 --- a/packages/libs/restate-sdk/src/endpoint.ts +++ b/packages/libs/restate-sdk/src/endpoint.ts @@ -73,13 +73,27 @@ export interface RestateEndpointBase { * Using winston: * ```ts * const logger = createLogger({ ... }) - * restate.setLogger((meta, message, ...o) => {logger.log(meta.level, {invocationId: meta.context?.invocationId}, [message, ...o].join(' '))}) + * restate.setLogger((meta, message, ...o) => { + * logger.log(meta.level, { + * invocationId: meta.context?.invocationId, + * ...meta.context?.additionalContext, + * message: [message, ...o].join(" "), + * }); + * }) * ``` * @example * Using pino: * ```ts * const logger = pino() - * restate.setLogger((meta, message, ...o) => {logger[meta.level]({invocationId: meta.context?.invocationId}, [message, ...o].join(' '))}) + * restate.setLogger((meta, message, ...o) => { + * logger[meta.level]( + * { + * invocationId: meta.context?.invocationId, + * ...meta.context?.additionalContext, + * }, + * [message, ...o].join(" ") + * ); + * }) * ``` */ setLogger(logger: LoggerTransport): E; diff --git a/packages/libs/restate-sdk/src/endpoint/types.ts b/packages/libs/restate-sdk/src/endpoint/types.ts index e2b7b526..b64e54b0 100644 --- a/packages/libs/restate-sdk/src/endpoint/types.ts +++ b/packages/libs/restate-sdk/src/endpoint/types.ts @@ -46,13 +46,27 @@ export interface EndpointOptions { * Using winston: * ```ts * const logger = createLogger({ ... }) - * createEndpointHandler({ logger: (meta, message, ...o) => {logger.log(meta.level, {invocationId: meta.context?.invocationId}, [message, ...o].join(' '))} }) + * createEndpointHandler({ logger: (meta, message, ...o) => { + * logger.log(meta.level, { + * invocationId: meta.context?.invocationId, + * ...meta.context?.additionalContext, + * message: [message, ...o].join(" "), + * }); + * } }) * ``` * @example * Using pino: * ```ts * const logger = pino() - * createEndpointHandler({ logger: (meta, message, ...o) => {logger[meta.level]({invocationId: meta.context?.invocationId}, [message, ...o].join(' '))}} ) + * createEndpointHandler({ logger: (meta, message, ...o) => { + * logger[meta.level]( + * { + * invocationId: meta.context?.invocationId, + * ...meta.context?.additionalContext, + * }, + * [message, ...o].join(" ") + * ); + * } }) * ``` */ logger?: LoggerTransport; diff --git a/packages/libs/restate-sdk/src/logging/logger.ts b/packages/libs/restate-sdk/src/logging/logger.ts index 4f94f189..1a1491bc 100644 --- a/packages/libs/restate-sdk/src/logging/logger.ts +++ b/packages/libs/restate-sdk/src/logging/logger.ts @@ -11,17 +11,17 @@ /* eslint-disable @typescript-eslint/no-explicit-any */ -import type { - LoggerContext, - LoggerTransport, - LogSource, -} from "./logger_transport.js"; -import { RestateLogLevel } from "./logger_transport.js"; +import type { LoggerTransport, LogSource } from "./logger_transport.js"; +import { LoggerContext, RestateLogLevel } from "./logger_transport.js"; +import type { RestateConsole } from "../context.js"; /** * Logging facade used internally by the Restate SDK. */ -export interface Logger extends Console { +export interface Logger extends RestateConsole { + /** + * Emits a log event at the provided Restate log level + */ logForLevel( level: RestateLogLevel, message?: any, @@ -35,6 +35,30 @@ export function createLogger( context?: LoggerContext, isReplaying: () => boolean = () => false ): Logger { + /** + * Builds the immutable context for a child logger by merging parent and child + * fields without mutating the parent logger context. + */ + function childLoggerContext( + context: LoggerContext | undefined, + additionalContext: Record + ): LoggerContext | undefined { + if (context === undefined) { + return undefined; + } + return new LoggerContext( + context.invocationId, + context.serviceName, + context.handlerName, + context.key, + context.request, + { + ...context.additionalContext, + ...additionalContext, + } + ); + } + function loggerForLevel( loggerTransport: LoggerTransport, source: LogSource, @@ -92,6 +116,18 @@ export function createLogger( isReplaying, context ), + child: { + get() { + return (additionalContext: Record): Logger => { + return createLogger( + loggerTransport, + source, + childLoggerContext(context, additionalContext), + isReplaying + ); + }; + }, + }, logForLevel: { get() { return ( diff --git a/packages/libs/restate-sdk/src/logging/logger_transport.ts b/packages/libs/restate-sdk/src/logging/logger_transport.ts index 49725c50..afcbddaa 100644 --- a/packages/libs/restate-sdk/src/logging/logger_transport.ts +++ b/packages/libs/restate-sdk/src/logging/logger_transport.ts @@ -56,6 +56,10 @@ export type LoggerTransport = ( /** * Logger context. + * + * The SDK fills invocation fields automatically. `additionalContext` contains + * fields added with `ctx.console.child(...)`, for example order ids or payment + * ids that should be attached to each log line. */ export class LoggerContext { readonly invocationTarget: string; diff --git a/packages/libs/restate-sdk/test/utils.test.ts b/packages/libs/restate-sdk/test/utils.test.ts index f8759a70..08c38002 100644 --- a/packages/libs/restate-sdk/test/utils.test.ts +++ b/packages/libs/restate-sdk/test/utils.test.ts @@ -11,6 +11,28 @@ import { RandImpl } from "../src/utils/rand.js"; import { describe, expect, it } from "vitest"; +import { createLogger } from "../src/logging/logger.js"; +import { + LoggerContext, + type LogMetadata, + LogSource, + type LoggerTransport, +} from "../src/logging/logger_transport.js"; + +type LogEvent = { + meta: LogMetadata; + message?: unknown; + optionalParams: unknown[]; +}; + +/** + * Creates a logger transport that records emitted log events for assertions. + */ +function collectingTransport(events: LogEvent[]): LoggerTransport { + return (meta, message, ...optionalParams) => { + events.push({ meta, message, optionalParams }); + }; +} describe("rand", () => { it("accepts seed", () => { @@ -95,3 +117,96 @@ describe("rand", () => { expect(actual).toStrictEqual(expected); }); }); + +describe("createLogger", () => { + it("adds child context to log metadata", () => { + const events: LogEvent[] = []; + const logger = createLogger( + collectingTransport(events), + LogSource.USER, + new LoggerContext( + "invocation-1", + "Greeter", + "greet", + undefined, + undefined, + { orderId: "order-1" } + ) + ); + + logger.child({ paymentId: "payment-1" }).info("charged"); + + expect(events).toHaveLength(1); + const event = events[0]!; + expect(event.message).toBe("charged"); + expect(event.meta.context?.additionalContext).toEqual({ + orderId: "order-1", + paymentId: "payment-1", + }); + }); + + it("accumulates nested child context without mutating parent loggers", () => { + const events: LogEvent[] = []; + const parentContext = new LoggerContext( + "invocation-1", + "Greeter", + "greet", + undefined, + undefined, + { orderId: "order-1", stage: "accepted" } + ); + const logger = createLogger( + collectingTransport(events), + LogSource.USER, + parentContext + ); + const paymentLogger = logger.child({ stage: "payment" }); + const authorizationLogger = paymentLogger.child({ + authorizationId: "authorization-1", + }); + + logger.info("parent"); + paymentLogger.info("payment"); + authorizationLogger.info("authorized"); + + expect(parentContext.additionalContext).toEqual({ + orderId: "order-1", + stage: "accepted", + }); + expect(events).toHaveLength(3); + expect(events[0]!.meta.context?.additionalContext).toEqual({ + orderId: "order-1", + stage: "accepted", + }); + expect(events[1]!.meta.context?.additionalContext).toEqual({ + orderId: "order-1", + stage: "payment", + }); + expect(events[2]!.meta.context?.additionalContext).toEqual({ + orderId: "order-1", + stage: "payment", + authorizationId: "authorization-1", + }); + }); + + it("evaluates replaying at log-call time for child loggers", () => { + const events: LogEvent[] = []; + let replaying = false; + const logger = createLogger( + collectingTransport(events), + LogSource.USER, + new LoggerContext("invocation-1", "Greeter", "greet"), + () => replaying + ); + const childLogger = logger.child({ orderId: "order-1" }); + + replaying = true; + childLogger.info("replay"); + replaying = false; + childLogger.info("processing"); + + expect(events).toHaveLength(2); + expect(events[0]!.meta.replaying).toBe(true); + expect(events[1]!.meta.replaying).toBe(false); + }); +});