chore: structured logging for Workers Logs

Author: ndisidore

AGENTS.md

@@ -56,3 +56,23 @@ IMPORTANT: Remember when using RPC to use promise pipelining whenever possible.
 IMPORTANT: When using React's useState(), the state value cannot be an RPC stub. At runtime, all stubs appear to be callable (because the system doesn't actually know if the stub points to a function on the server side or not). But the setter returned by useState() has different behavior if passed a function (including any callable object): it calls the function in order to get the state. In order to avoid this problem, whenever a useState() state will contain an RpcStub, it's important to wrap the stub in an object, and set the state to that object instead.
 
 IMPORTANT: RPC stubs must be disposed to prevent resource leaks on the server side. Call `stub[Symbol.dispose]()` when the stub is no longer needed (or use a `using` declaration where possible). In particular, when a React component obtains a stub in a useEffect, the cleanup function should dispose the stub.
+
+IMPORTANT: Server-side logging uses `@gadgets/backend-utils/logger` (frontend browser `console.*` is out of scope):
+- Define a package-owned field type and module-scoped logger with a stable dot-separated `component`
+  and, for gatekeepers, `vendorId`:
+  `const logger = createLogger<GitHubLogFields>({ component: "gatekeeper.github", vendorId: VENDOR_ID });`.
+- Emit concrete event names and relevant typed fields, for example:
+  `logger.warn("failed to notify credential expiry", { event: "credentials.expiry.notify.failed", error: err });`.
+  Each call emits one indexed object; module/child fields such as `vendorId` are inherited.
+- Use immutable `logger.with(fields)` for object-owned or nearby context. Prefer module/object loggers
+  over logger parameters, and do not replace a shallow child logger with ambient context just to
+  remove a local variable.
+- For bounded operation context needed by deep helpers or independent loggers, use `createLogger`
+  and `withLogContext` from `@gadgets/backend-utils/context-logger`. Re-establish it per operation;
+  it does not cross RPC, hibernation, or restart, and requires `nodejs_als` or `nodejs_compat`.
+- Pass caught values as `error`. The helper stringifies `Error` instances and primitives, uses an
+  own string `message` for plain objects, omits `undefined`, and adds stacks to all `Error` logs.
+  Keep this normalization deliberately small; do not traverse causes or copy arbitrary properties.
+- Extend field vocabularies locally. Levels: `error` needs attention, `warn` continues best-effort,
+  `info` is notable lifecycle, and `debug` is noisy breadcrumbs. Never log secrets, prompts, headers,
+  tokens, or request/response bodies.

packages/backend-utils/README.md

@@ -0,0 +1,8 @@
+# Backend utilities
+
+`@gadgets/backend-utils` is a shared library for code that runs in Cloudflare Workers. It is not a
+standalone Worker and has no deployable entrypoint or Wrangler project configuration.
+
+The package's Vitest configuration uses the Workers test pool to exercise runtime-specific APIs.
+Consumers that import `@gadgets/backend-utils/context-logger` must enable `nodejs_als` (or
+`nodejs_compat`); the default `@gadgets/backend-utils/logger` entry point has no such requirement.

packages/backend-utils/__tests__/logger.test.ts

@@ -0,0 +1,278 @@
+import { afterEach, describe, expect, it, vi } from "vitest";
+import { createLogger as createBaseLogger } from "../src/logger.js";
+import { createLogger, withLogContext } from "../src/context-logger.js";
+
+type TestLogFields = {
+  accountId?: number;
+  collectionId?: string;
+  operation?: string;
+  outcome?: string;
+  vendorId?: string;
+};
+
+describe("worker logger", () => {
+  afterEach(() => vi.restoreAllMocks());
+
+  it("emits the message and structured context as one indexed object", () => {
+    let spy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    let logger = createLogger<TestLogFields>({ component: "workshop.user" });
+
+    logger.warn("failed to load vendor", {
+      event: "gatekeeper.vendor.load.failed",
+      vendorId: "github",
+    });
+
+    expect(spy).toHaveBeenCalledWith({
+      message: "failed to load vendor",
+      event: "gatekeeper.vendor.load.failed",
+      component: "workshop.user",
+      vendorId: "github",
+    });
+  });
+
+  it("derives immutable child loggers", () => {
+    let spy = vi.spyOn(console, "info").mockImplementation(() => {});
+    let logger = createLogger<TestLogFields>({ component: "workshop.user" });
+    let accountLogger = logger.with({ accountId: 7 });
+
+    accountLogger.info("account disconnected", {
+      event: "account.disconnected",
+      outcome: "ok",
+    });
+    logger.info("account listing finished", {
+      event: "account.list.finished",
+      outcome: "ok",
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ accountId: 7 });
+    expect(spy.mock.calls[1]?.[0]).not.toHaveProperty("accountId");
+  });
+
+  it("chains child context with nearest values taking precedence", () => {
+    const spy = vi.spyOn(console, "info").mockImplementation(() => {});
+    const logger = createLogger<TestLogFields>({
+      component: "gatekeeper.context", vendorId: "context",
+    });
+    const collectionLogger = logger.with({
+      operation: "collection.sync",
+      collectionId: "collection-1",
+      outcome: "started",
+    });
+    const retryLogger = collectionLogger.with({ collectionId: "collection-2" });
+
+    retryLogger.info("collection sync finished", {
+      event: "collection.sync.finished",
+      outcome: "ok",
+    });
+
+    expect(spy).toHaveBeenCalledWith({
+      message: "collection sync finished",
+      component: "gatekeeper.context",
+      vendorId: "context",
+      operation: "collection.sync",
+      collectionId: "collection-2",
+      event: "collection.sync.finished",
+      outcome: "ok",
+    });
+  });
+
+  it("keeps explicit child context ahead of ambient context", () => {
+    const spy = vi.spyOn(console, "info").mockImplementation(() => {});
+    const logger = createLogger<TestLogFields>({ component: "workshop.overseer" })
+      .with({ operation: "agent.run" });
+
+    withLogContext({ operation: "ambient.operation" }, () => {
+      logger.info("child wins", { event: "precedence.child" });
+      logger.info("details win", { event: "precedence.details", operation: "log.call" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ operation: "agent.run" });
+    expect(spy.mock.calls[1]?.[0]).toMatchObject({ operation: "log.call" });
+  });
+
+  it("pins component against ambient collisions", () => {
+    const spy = vi.spyOn(console, "info").mockImplementation(() => {});
+    const logger = createLogger({ component: "workshop.overseer" });
+    const runWithUnsafeContext = withLogContext as unknown as (
+      fields: Record<string, string>, callback: () => void,
+    ) => void;
+
+    runWithUnsafeContext({ component: "spoofed.component" }, () => {
+      logger.info("component stays fixed", { event: "component.fixed" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ component: "workshop.overseer" });
+  });
+
+  it("adds package-local fields to child loggers", () => {
+    const spy = vi.spyOn(console, "debug").mockImplementation(() => {});
+    const logger = createLogger<{ providerRequestId?: string }>({ component: "workshop.agent" });
+    const requestLogger = logger.with({ providerRequestId: "request-1" });
+
+    requestLogger.debug("provider request started", { event: "provider.request.started" });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ providerRequestId: "request-1" });
+  });
+
+  it("inherits nested async context and restores its parent", async () => {
+    let spy = vi.spyOn(console, "debug").mockImplementation(() => {});
+    let logger = createLogger({ component: "workshop.overseer" });
+
+    await withLogContext({ operation: "agent.run", gadgetId: "gadget-1" }, async () => {
+      await withLogContext({ chatId: 3 }, async () => {
+        await Promise.resolve();
+        logger.debug("nested", { event: "nested" });
+      });
+      logger.debug("parent", { event: "parent" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({
+      operation: "agent.run",
+      gadgetId: "gadget-1",
+      chatId: 3,
+    });
+    expect(spy.mock.calls[1]?.[0]).not.toHaveProperty("chatId");
+  });
+
+  it("isolates concurrent async contexts", async () => {
+    let spy = vi.spyOn(console, "debug").mockImplementation(() => {});
+    let logger = createLogger({ component: "workshop.overseer" });
+    let ready = 0;
+    let release!: () => void;
+    const gate = new Promise<void>(resolve => { release = resolve; });
+
+    const runs = Promise.all([
+      withLogContext({ chatId: 1 }, async () => {
+        ++ready;
+        await gate;
+        logger.debug("first", { event: "first" });
+      }),
+      withLogContext({ chatId: 2 }, async () => {
+        ++ready;
+        await gate;
+        logger.debug("second", { event: "second" });
+      }),
+    ]);
+    expect(ready).toBe(2);
+    release();
+    await runs;
+    logger.debug("outside", { event: "outside" });
+
+    let logs = spy.mock.calls.map(([entry]) => entry);
+    expect(logs).toContainEqual(expect.objectContaining({ event: "first", chatId: 1 }));
+    expect(logs).toContainEqual(expect.objectContaining({ event: "second", chatId: 2 }));
+    expect(logs.find(entry => entry.event === "outside")).not.toHaveProperty("chatId");
+  });
+
+  it("shares async context across independently created loggers", async () => {
+    const spy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    const overseerLogger = createLogger({ component: "workshop.overseer" });
+    const agentLogger = createLogger({ component: "workshop.agent" });
+
+    await withLogContext({ operation: "agent.run", gadgetId: "gadget-1", chatId: 3 }, async () => {
+      overseerLogger.warn("overseer warning", { event: "overseer.warning" });
+      await Promise.resolve();
+      agentLogger.warn("agent warning", { event: "agent.warning" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({
+      component: "workshop.overseer",
+      operation: "agent.run",
+      gadgetId: "gadget-1",
+      chatId: 3,
+    });
+    expect(spy.mock.calls[1]?.[0]).toMatchObject({
+      component: "workshop.agent",
+      operation: "agent.run",
+      gadgetId: "gadget-1",
+      chatId: 3,
+    });
+  });
+
+  it("does not impose ambient context on the base logger", () => {
+    const spy = vi.spyOn(console, "info").mockImplementation(() => {});
+    const logger = createBaseLogger<{ operation?: string }>({ component: "gatekeeper.github" });
+
+    withLogContext({ operation: "agent.run" }, () => {
+      logger.info("base logger event", { event: "base.logger.event" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).not.toHaveProperty("operation");
+  });
+
+  it("preserves context after awaiting a custom thenable", async () => {
+    const spy = vi.spyOn(console, "debug").mockImplementation(() => {});
+    const logger = createLogger({ component: "workshop.overseer" });
+    const thenable: PromiseLike<void> = {
+      // oxlint-disable-next-line unicorn/no-thenable -- Deliberately models an RPC promise.
+      then(resolve) {
+        queueMicrotask(() => resolve());
+        return Promise.resolve();
+      },
+    };
+
+    await withLogContext({ operation: "agent.run" }, async () => {
+      await thenable;
+      logger.debug("after thenable", { event: "after.thenable" });
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ operation: "agent.run" });
+  });
+
+  it("normalizes errors and adds stacks at every level", () => {
+    let errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
+    let warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    let logger = createLogger({ component: "workshop.agent" });
+    let error = new Error("boom");
+
+    logger.error("agent failed", { event: "agent.failed", error });
+    logger.warn("agent recovered", { event: "agent.recovered", error });
+
+    expect(errorSpy.mock.calls[0]?.[0]).toMatchObject({
+      error: "Error: boom",
+      errorStack: expect.stringContaining("Error: boom"),
+    });
+    expect(warnSpy.mock.calls[0]?.[0]).toMatchObject({ error: "Error: boom" });
+    expect(warnSpy.mock.calls[0]?.[0]).toMatchObject({
+      errorStack: expect.stringContaining("Error: boom"),
+    });
+  });
+
+  it("omits undefined errors", () => {
+    const spy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    const logger = createLogger({ component: "workshop.agent" });
+
+    logger.warn("undefined error", { event: "undefined.error", error: undefined });
+
+    expect(spy.mock.calls[0]?.[0]).not.toHaveProperty("error");
+  });
+
+  it("uses an own string message without serializing object contents", () => {
+    const spy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    const logger = createLogger({ component: "workshop.agent" });
+
+    logger.warn("object error", {
+      event: "object.error", error: { message: "safe summary", tokenValue: "do not log" },
+    });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({ error: "safe summary" });
+    expect(JSON.stringify(spy.mock.calls[0]?.[0])).not.toContain("do not log");
+  });
+
+  it("does not traverse error causes or copy arbitrary properties", () => {
+    const spy = vi.spyOn(console, "warn").mockImplementation(() => {});
+    const logger = createLogger({ component: "workshop.agent" });
+    const cause = Object.assign(new Error("inner"), { tokenValue: "do not log" });
+    const error = Object.assign(new Error("outer", { cause }), { responseBody: "do not log" });
+
+    logger.warn("caused error", { event: "caused.error", error });
+
+    expect(spy.mock.calls[0]?.[0]).toMatchObject({
+      error: "Error: outer",
+      errorStack: expect.stringContaining("Error: outer"),
+    });
+    const serialized = JSON.stringify(spy.mock.calls[0]?.[0]);
+    expect(serialized).not.toContain("Error: inner");
+    expect(serialized).not.toContain("do not log");
+  });
+});

packages/backend-utils/__tests__/type-tests.ts

@@ -0,0 +1,63 @@
+import { createLogger } from "../src/logger.js";
+import { withLogContext } from "../src/context-logger.js";
+
+let logger = createLogger<{
+  accountId?: number;
+  chatId?: number;
+  durationMs?: number;
+  providerRequestId?: string;
+}>({ component: "test" });
+let loggerWithoutPackageFields = createLogger({ component: "test" });
+let loggerWithSensitivePackageFields = createLogger<{
+  body?: string;
+  header?: string;
+  headers?: string;
+  prompt?: string;
+  secret?: string;
+  token?: string;
+}>({ component: "test" });
+// @ts-expect-error sensitive fields cannot be logger defaults even when declared
+createLogger<{ token?: string }>({ component: "test", token: "private token" });
+logger.info("valid", { event: "valid", accountId: 1, providerRequestId: "request-1" });
+logger.with({ chatId: 1 });
+logger.with({ providerRequestId: "request-2" });
+withLogContext({ operation: "test.operation" }, () => {});
+// @ts-expect-error sensitive fields are not accepted in ambient context
+withLogContext({ token: "private token" }, () => {});
+// @ts-expect-error errors belong to individual log entries, not ambient context
+withLogContext({ error: "boom" }, () => {});
+// @ts-expect-error error stacks are produced by the logger, not ambient context
+withLogContext({ errorStack: "stack" }, () => {});
+// @ts-expect-error components are fixed when a logger is created
+withLogContext({ component: "other" }, () => {});
+// @ts-expect-error events belong to individual log entries, not ambient context
+withLogContext({ event: "other" }, () => {});
+// @ts-expect-error messages are the first argument to a log method
+withLogContext({ message: "other" }, () => {});
+
+// @ts-expect-error event is required
+logger.info("missing event", { accountId: 1 });
+// @ts-expect-error misspelled package field
+logger.info("misspelled", { event: "invalid", acountId: 1 });
+// @ts-expect-error invalid shared field type
+logger.info("wrong type", { event: "invalid", durationMs: "slow" });
+// @ts-expect-error sensitive fields are not accepted
+logger.info("sensitive", { event: "invalid", body: "secret" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.info("sensitive", { event: "invalid", body: "secret" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.with({ header: "authorization" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.with({ headers: "authorization" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.with({ prompt: "private prompt" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.with({ secret: "private secret" });
+// @ts-expect-error sensitive fields remain prohibited when declared in the package vocabulary
+loggerWithSensitivePackageFields.with({ token: "private token" });
+// @ts-expect-error misspelled package-local field
+logger.with({ providerRequstId: "request-3" });
+// @ts-expect-error errors belong to individual log entries, not inherited logger context
+logger.with({ error: new Error("boom") });
+// @ts-expect-error package fields must be declared on this logger
+loggerWithoutPackageFields.info("undeclared", { event: "invalid", accountId: 1 });