From a15a7716a0f8e2c56c1ed0e2c81ddda4f25f0313 Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 16:52:55 +0300 Subject: [PATCH 1/7] add context logger to ts sdk --- packages/libs/restate-sdk/src/common_api.ts | 1 + packages/libs/restate-sdk/src/context.ts | 13 +- packages/libs/restate-sdk/src/context_impl.ts | 3 +- .../libs/restate-sdk/src/logging/logger.ts | 43 +++++-- packages/libs/restate-sdk/test/utils.test.ts | 112 ++++++++++++++++++ 5 files changed, 163 insertions(+), 9 deletions(-) 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..6c36764f 100644 --- a/packages/libs/restate-sdk/src/context.ts +++ b/packages/libs/restate-sdk/src/context.ts @@ -257,6 +257,17 @@ export type GenericSend = { name?: string; }; +/** + * Console to use for logging + */ +export type RestateConsole = Console & { + /** + * Creates a child console that attaches the provided contextual fields to each + * log event + */ + child(context: Record): RestateConsole; +}; + /** * The context that gives access to all Restate-backed operations, for example * - sending reliable messages / RPC through Restate @@ -284,7 +295,7 @@ 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. */ - 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/logging/logger.ts b/packages/libs/restate-sdk/src/logging/logger.ts index 4f94f189..64358723 100644 --- a/packages/libs/restate-sdk/src/logging/logger.ts +++ b/packages/libs/restate-sdk/src/logging/logger.ts @@ -11,17 +11,14 @@ /* 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 { logForLevel( level: RestateLogLevel, message?: any, @@ -35,6 +32,26 @@ export function createLogger( context?: LoggerContext, isReplaying: () => boolean = () => false ): Logger { + 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 +109,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/test/utils.test.ts b/packages/libs/restate-sdk/test/utils.test.ts index f8759a70..9f896a2f 100644 --- a/packages/libs/restate-sdk/test/utils.test.ts +++ b/packages/libs/restate-sdk/test/utils.test.ts @@ -11,6 +11,25 @@ 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[]; +}; + +function collectingTransport(events: LogEvent[]): LoggerTransport { + return (meta, message, ...optionalParams) => { + events.push({ meta, message, optionalParams }); + }; +} describe("rand", () => { it("accepts seed", () => { @@ -95,3 +114,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); + }); +}); From d6b20b12d663c214706b1b5fdad8b748e1e136bd Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 16:53:09 +0300 Subject: [PATCH 2/7] add an example --- packages/examples/node/package.json | 1 + packages/examples/node/src/logger_context.ts | 74 ++++++++++++++++++++ 2 files changed, 75 insertions(+) create mode 100644 packages/examples/node/src/logger_context.ts 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..6fa6e91c --- /dev/null +++ b/packages/examples/node/src/logger_context.ts @@ -0,0 +1,74 @@ +/* + * 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 { 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; + +async function chargePayment(input: CheckoutRequest): Promise { + return { + paymentId: `payment-${input.paymentMethodId}`, + }; +} + +async function createShipment( + orderId: string +): Promise<{ shipmentId: string }> { + return { + shipmentId: `shipment-${orderId}`, + }; +} + +serve({ services: [checkout] }); From ebca88d25556f084f82e3765cb5952a41174106c Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 16:53:16 +0300 Subject: [PATCH 3/7] add context logger e2e test --- .../e2e/logger_context.e2e.test.ts | 237 ++++++++++++++++++ 1 file changed, 237 insertions(+) create mode 100644 packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts 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..34120a83 --- /dev/null +++ b/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts @@ -0,0 +1,237 @@ +/* + * 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"; + +const wait = (ms: number) => new Promise((r) => setTimeout(r, ms)); + +type LoggerContextHandoffInput = { + orderId: string; + paymentId: string; +}; + +const loggerContextHandoff = restate.service({ + name: "loggerContextHandoff", + handlers: { + run: async ( + ctx: restate.Context, + input: LoggerContextHandoffInput + ): 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-handoff"); + await ctx.sleep(2_000, "worker-handoff"); + log.info("after-handoff"); + + return "done"; + }, + }, +}); + +type CapturedLogEvent = { + worker: string; + message: string; + replaying: boolean; + source: string; + additionalContext: Record; +}; + +function captureLogger( + worker: string, + events: CapturedLogEvent[] +): restate.LoggerTransport { + return (meta, message) => { + if (message !== "before-handoff" && message !== "after-handoff") { + return; + } + + events.push({ + worker, + message: String(message), + replaying: meta.replaying, + source: String(meta.source), + additionalContext: { ...(meta.context?.additionalContext ?? {}) }, + }); + }; +} + +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)}` + ); +} + +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(); + } + } + }, + }; +} + +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(); + }); + }); +} + +async function startLoggerContextWorker( + port: number, + logger: restate.LoggerTransport +): Promise { + const handler = restate.createEndpointHandler({ + services: [loggerContextHandoff], + logger, + }); + const server = http2.createServer(handler); + + await new Promise((resolve, reject) => { + server + .listen(port) + .once("listening", () => resolve()) + .once("error", reject); + }); + + return server; +} + +describe("logger context worker handoff", () => { + 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: [loggerContextHandoff], + 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(loggerContextHandoff); + const input = { + orderId: "order-worker-handoff", + paymentId: "payment-worker-handoff", + }; + + const result = client.run(input); + const worker1Before = await waitForLogEvent( + events, + (event) => + event.worker === "worker-1" && + event.message === "before-handoff" && + !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-handoff" && + event.replaying + ); + const worker2After = await waitForLogEvent( + events, + (event) => + event.worker === "worker-2" && + event.message === "after-handoff" && + !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-handoff" + ) + ).toBe(false); + } finally { + if (replacementWorker) { + await closeHttp2Server(replacementWorker, replacementTracker); + } + if (env) { + await closeHttp2Server(env.startedRestateHttpServer, originalTracker); + await env.startedRestateContainer.stop(); + } + } + }, 30_000); +}); From 475d71ac8752bef3d88ab45a1a6e3f13cadc127d Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 17:09:29 +0300 Subject: [PATCH 4/7] docs for the context logger --- packages/libs/restate-sdk/README.md | 32 ++++++++++++++++++ packages/libs/restate-sdk/src/context.ts | 33 +++++++++++++++++-- packages/libs/restate-sdk/src/endpoint.ts | 18 ++++++++-- .../libs/restate-sdk/src/endpoint/types.ts | 18 ++++++++-- .../src/logging/logger_transport.ts | 4 +++ 5 files changed, 98 insertions(+), 7 deletions(-) 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/context.ts b/packages/libs/restate-sdk/src/context.ts index 6c36764f..07738bde 100644 --- a/packages/libs/restate-sdk/src/context.ts +++ b/packages/libs/restate-sdk/src/context.ts @@ -258,12 +258,38 @@ export type GenericSend = { }; /** - * Console to use for logging + * 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 + * log event. + * + * 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; }; @@ -293,7 +319,8 @@ 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: RestateConsole; 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_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; From f3cfe398646f05be03715a58cb74bd1359493b2d Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 17:29:26 +0300 Subject: [PATCH 5/7] additional test on retry --- .../e2e/logger_context.e2e.test.ts | 127 +++++++++++++++++- 1 file changed, 125 insertions(+), 2 deletions(-) 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 index 34120a83..eda6ff10 100644 --- a/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts +++ b/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts @@ -23,6 +23,23 @@ type LoggerContextHandoffInput = { paymentId: string; }; +const retryStepCount = 5; + +type LoggerContextRetryInput = { + workflowId: string; +}; + +type RetryContext = Record; + +const retryAttempts = new Map(); + +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 loggerContextHandoff = restate.service({ name: "loggerContextHandoff", handlers: { @@ -46,6 +63,42 @@ const loggerContextHandoff = restate.service({ }, }); +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; @@ -56,10 +109,11 @@ type CapturedLogEvent = { function captureLogger( worker: string, - events: CapturedLogEvent[] + events: CapturedLogEvent[], + messages = new Set(["before-handoff", "after-handoff"]) ): restate.LoggerTransport { return (meta, message) => { - if (message !== "before-handoff" && message !== "after-handoff") { + if (!messages.has(String(message))) { return; } @@ -152,6 +206,26 @@ async function startLoggerContextWorker( return server; } +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; +} + +function retryLogMessages(): Set { + return new Set( + Array.from({ length: retryStepCount }, (_, index) => { + return `after-step-${index + 1}`; + }) + ); +} + describe("logger context worker handoff", () => { test("rebuilds child logger context after worker restart", async () => { const events: CapturedLogEvent[] = []; @@ -235,3 +309,52 @@ describe("logger context worker handoff", () => { } }, 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); +}); From 8b4ccadbb61a6684d3d0b6d1e10d2e9ca27b8478 Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 17:40:00 +0300 Subject: [PATCH 6/7] update comments --- .changeset/fuzzy-logger-context.md | 5 ++ packages/examples/node/src/logger_context.ts | 10 ++- .../e2e/logger_context.e2e.test.ts | 80 ++++++++++++++----- packages/libs/restate-sdk/src/context.ts | 1 + .../libs/restate-sdk/src/logging/logger.ts | 10 +++ packages/libs/restate-sdk/test/utils.test.ts | 3 + 6 files changed, 89 insertions(+), 20 deletions(-) create mode 100644 .changeset/fuzzy-logger-context.md 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/src/logger_context.ts b/packages/examples/node/src/logger_context.ts index 6fa6e91c..efe44c1b 100644 --- a/packages/examples/node/src/logger_context.ts +++ b/packages/examples/node/src/logger_context.ts @@ -44,7 +44,9 @@ const checkout = service({ return await createShipment(input.orderId); }); - contextLogger.child({ shipmentId: shipment.shipmentId }).info("shipment created"); + contextLogger + .child({ shipmentId: shipment.shipmentId }) + .info("shipment created"); return { orderId: input.orderId, @@ -57,12 +59,18 @@ const checkout = service({ 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 }> { 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 index eda6ff10..0f67111c 100644 --- a/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts +++ b/packages/libs/restate-sdk-gen/e2e/logger_context.e2e.test.ts @@ -16,9 +16,12 @@ 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 LoggerContextHandoffInput = { +type LoggerContextWorkerRestartInput = { orderId: string; paymentId: string; }; @@ -33,6 +36,14 @@ 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; @@ -40,12 +51,12 @@ function bumpRetryAttempt(workflowId: string, step: number): number { return attempt; } -const loggerContextHandoff = restate.service({ - name: "loggerContextHandoff", +const loggerContextWorkerRestart = restate.service({ + name: "loggerContextWorkerRestart", handlers: { run: async ( ctx: restate.Context, - input: LoggerContextHandoffInput + input: LoggerContextWorkerRestartInput ): Promise => { let log = ctx.console.child({ orderId: input.orderId }); @@ -54,9 +65,9 @@ const loggerContextHandoff = restate.service({ })); log = log.child({ paymentId: payment.paymentId }); - log.info("before-handoff"); - await ctx.sleep(2_000, "worker-handoff"); - log.info("after-handoff"); + log.info("before-worker-restart"); + await ctx.sleep(2_000, "worker-restart"); + log.info("after-worker-restart"); return "done"; }, @@ -107,13 +118,23 @@ type CapturedLogEvent = { 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[], - messages = new Set(["before-handoff", "after-handoff"]) + capturedMessages = workerRestartMessages ): restate.LoggerTransport { return (meta, message) => { - if (!messages.has(String(message))) { + if (!capturedMessages.has(String(message))) { return; } @@ -127,6 +148,9 @@ function captureLogger( }; } +/** + * Polls until a captured log event matching the predicate is observed. + */ async function waitForLogEvent( events: CapturedLogEvent[], predicate: (event: CapturedLogEvent) => boolean, @@ -146,6 +170,10 @@ async function waitForLogEvent( ); } +/** + * 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; } { @@ -166,6 +194,10 @@ function trackHttp2Sessions(server: http2.Http2Server): { }; } +/** + * Closes an HTTP/2 server and optionally destroys tracked sessions if graceful + * shutdown stalls. + */ async function closeHttp2Server( server: http2.Http2Server, tracker?: { destroySessions: () => void } @@ -186,12 +218,15 @@ async function closeHttp2Server( }); } +/** + * 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: [loggerContextHandoff], + services: [loggerContextWorkerRestart], logger, }); const server = http2.createServer(handler); @@ -206,6 +241,9 @@ async function startLoggerContextWorker( 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", @@ -218,6 +256,9 @@ function expectedRetryContext(upToStep = retryStepCount): RetryContext { 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) => { @@ -226,7 +267,7 @@ function retryLogMessages(): Set { ); } -describe("logger context worker handoff", () => { +describe("logger context worker restart", () => { test("rebuilds child logger context after worker restart", async () => { const events: CapturedLogEvent[] = []; let env: RestateTestEnvironment | undefined; @@ -236,7 +277,7 @@ describe("logger context worker handoff", () => { try { env = await RestateTestEnvironment.start({ - services: [loggerContextHandoff], + services: [loggerContextWorkerRestart], logger: captureLogger("worker-1", events), }); originalTracker = trackHttp2Sessions(env.startedRestateHttpServer); @@ -244,10 +285,10 @@ describe("logger context worker handoff", () => { env.startedRestateHttpServer.address() as net.AddressInfo; const workerPort = workerAddress.port; const rs = sdkClients.connect({ url: env.baseUrl() }); - const client = rs.serviceClient(loggerContextHandoff); + const client = rs.serviceClient(loggerContextWorkerRestart); const input = { - orderId: "order-worker-handoff", - paymentId: "payment-worker-handoff", + orderId: "order-worker-restart", + paymentId: "payment-worker-restart", }; const result = client.run(input); @@ -255,7 +296,7 @@ describe("logger context worker handoff", () => { events, (event) => event.worker === "worker-1" && - event.message === "before-handoff" && + event.message === "before-worker-restart" && !event.replaying ); @@ -277,14 +318,14 @@ describe("logger context worker handoff", () => { events, (event) => event.worker === "worker-2" && - event.message === "before-handoff" && + event.message === "before-worker-restart" && event.replaying ); const worker2After = await waitForLogEvent( events, (event) => event.worker === "worker-2" && - event.message === "after-handoff" && + event.message === "after-worker-restart" && !event.replaying ); @@ -295,7 +336,8 @@ describe("logger context worker handoff", () => { expect( events.some( (event) => - event.worker === "worker-1" && event.message === "after-handoff" + event.worker === "worker-1" && + event.message === "after-worker-restart" ) ).toBe(false); } finally { diff --git a/packages/libs/restate-sdk/src/context.ts b/packages/libs/restate-sdk/src/context.ts index 07738bde..5c6ad249 100644 --- a/packages/libs/restate-sdk/src/context.ts +++ b/packages/libs/restate-sdk/src/context.ts @@ -268,6 +268,7 @@ 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 diff --git a/packages/libs/restate-sdk/src/logging/logger.ts b/packages/libs/restate-sdk/src/logging/logger.ts index 64358723..7857be22 100644 --- a/packages/libs/restate-sdk/src/logging/logger.ts +++ b/packages/libs/restate-sdk/src/logging/logger.ts @@ -19,6 +19,9 @@ import type { RestateConsole } from "../context.js"; * Logging facade used internally by the Restate SDK. */ export interface Logger extends RestateConsole { + /** + * Emits a log event at the provided Restate log level + */ logForLevel( level: RestateLogLevel, message?: any, @@ -32,6 +35,10 @@ 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 @@ -52,6 +59,9 @@ export function createLogger( ); } + /** + * Creates a lazily-bound console method for a specific log level. + */ function loggerForLevel( loggerTransport: LoggerTransport, source: LogSource, diff --git a/packages/libs/restate-sdk/test/utils.test.ts b/packages/libs/restate-sdk/test/utils.test.ts index 9f896a2f..08c38002 100644 --- a/packages/libs/restate-sdk/test/utils.test.ts +++ b/packages/libs/restate-sdk/test/utils.test.ts @@ -25,6 +25,9 @@ type LogEvent = { 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 }); From 6b3825a263ee98b092dfd8d1b5441b26e6c8719c Mon Sep 17 00:00:00 2001 From: seva Date: Sat, 30 May 2026 17:49:42 +0300 Subject: [PATCH 7/7] small fixes --- packages/examples/node/src/logger_context.ts | 11 ----------- packages/libs/restate-sdk/src/logging/logger.ts | 3 --- 2 files changed, 14 deletions(-) diff --git a/packages/examples/node/src/logger_context.ts b/packages/examples/node/src/logger_context.ts index efe44c1b..e4da8c9c 100644 --- a/packages/examples/node/src/logger_context.ts +++ b/packages/examples/node/src/logger_context.ts @@ -1,14 +1,3 @@ -/* - * 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 { service, serve, type Context } from "@restatedev/restate-sdk"; interface CheckoutRequest { diff --git a/packages/libs/restate-sdk/src/logging/logger.ts b/packages/libs/restate-sdk/src/logging/logger.ts index 7857be22..1a1491bc 100644 --- a/packages/libs/restate-sdk/src/logging/logger.ts +++ b/packages/libs/restate-sdk/src/logging/logger.ts @@ -59,9 +59,6 @@ export function createLogger( ); } - /** - * Creates a lazily-bound console method for a specific log level. - */ function loggerForLevel( loggerTransport: LoggerTransport, source: LogSource,