diff --git a/docs/packages/producer.mdx b/docs/packages/producer.mdx index 1aea88a94..88ffb07ed 100644 --- a/docs/packages/producer.mdx +++ b/docs/packages/producer.mdx @@ -245,6 +245,46 @@ The producer also re-exports key engine functionality for convenience: | `resolveRenderPaths()` | Resolve render directory paths | | `prepareHyperframeLintBody()` / `runHyperframeLint()` | Linting utilities | +## Logging + +The producer ships a small pluggable logger so callers can inject Pino, Winston, or any structured backend without taking a dependency on it. + +```ts +export type LogLevel = "error" | "warn" | "info" | "debug"; + +export interface ProducerLogger { + error(message: string, meta?: Record): void; + warn(message: string, meta?: Record): void; + info(message: string, meta?: Record): void; + debug(message: string, meta?: Record): void; + isLevelEnabled?(level: LogLevel): boolean; +} +``` + +`createConsoleLogger(level)` returns a console-backed implementation that filters by level and JSON-stringifies the optional `meta` object. `defaultLogger` is the singleton at `level="info"`. + +### Skipping expensive metadata in hot paths + +`isLevelEnabled` is **optional** so existing custom loggers keep working unchanged. When you build a non-trivial meta object in a hot loop just to attach to a debug log, gate the construction with the nullish-coalescing pattern so production runs (`level=info`) pay nothing while loggers without the method behave exactly as before: + +```ts +// Inside a per-frame loop in the encode pipeline: +if (i % 30 === 0 && (log.isLevelEnabled?.("debug") ?? true)) { + const hdrEl = stackingInfo.find((e) => e.isHdr); + log.debug("[Render] HDR layer composite frame", { + frame: i, + time: time.toFixed(2), + hdrElement: hdrEl + ? { z: hdrEl.zIndex, visible: hdrEl.visible, width: hdrEl.width } + : null, + stackingCount: stackingInfo.length, + activeTransition: activeTransition?.shader, + }); +} +``` + +The `?? true` fallback means callers using a custom logger that does not implement `isLevelEnabled` continue to build and pass the meta object — the optimization is opt-in for logger implementations that want it. + ## Regression Testing The producer includes a regression harness for comparing render output against golden baselines. This is useful for catching visual regressions when changing the runtime, engine, or rendering pipeline. diff --git a/packages/producer/src/logger.test.ts b/packages/producer/src/logger.test.ts new file mode 100644 index 000000000..f4d1f66c9 --- /dev/null +++ b/packages/producer/src/logger.test.ts @@ -0,0 +1,254 @@ +import { afterEach, beforeEach, describe, expect, it, mock } from "bun:test"; +import { createConsoleLogger, defaultLogger } from "./logger.js"; +import type { LogLevel, ProducerLogger } from "./logger.js"; + +describe("createConsoleLogger", () => { + // We capture calls to console.{log,warn,error} via `mock` so we can + // assert what would have been printed without polluting test output. + let logSpy: ReturnType; + let warnSpy: ReturnType; + let errorSpy: ReturnType; + let origLog: typeof console.log; + let origWarn: typeof console.warn; + let origError: typeof console.error; + + beforeEach(() => { + origLog = console.log; + origWarn = console.warn; + origError = console.error; + logSpy = mock(() => {}); + warnSpy = mock(() => {}); + errorSpy = mock(() => {}); + console.log = logSpy as unknown as typeof console.log; + console.warn = warnSpy as unknown as typeof console.warn; + console.error = errorSpy as unknown as typeof console.error; + }); + + afterEach(() => { + console.log = origLog; + console.warn = origWarn; + console.error = origError; + }); + + describe("level filtering", () => { + it("level=info drops debug, keeps info/warn/error", () => { + const log = createConsoleLogger("info"); + log.debug("debug-msg"); + log.info("info-msg"); + log.warn("warn-msg"); + log.error("error-msg"); + + expect(logSpy.mock.calls.length).toBe(1); + expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] info-msg"); + expect(warnSpy.mock.calls.length).toBe(1); + expect(warnSpy.mock.calls[0]?.[0]).toBe("[WARN] warn-msg"); + expect(errorSpy.mock.calls.length).toBe(1); + expect(errorSpy.mock.calls[0]?.[0]).toBe("[ERROR] error-msg"); + }); + + it("level=debug keeps all four levels", () => { + const log = createConsoleLogger("debug"); + log.debug("d"); + log.info("i"); + log.warn("w"); + log.error("e"); + + // info + debug both go to console.log + expect(logSpy.mock.calls.length).toBe(2); + expect(logSpy.mock.calls[0]?.[0]).toBe("[DEBUG] d"); + expect(logSpy.mock.calls[1]?.[0]).toBe("[INFO] i"); + expect(warnSpy.mock.calls.length).toBe(1); + expect(errorSpy.mock.calls.length).toBe(1); + }); + + it("level=warn drops info and debug, keeps warn/error", () => { + const log = createConsoleLogger("warn"); + log.debug("d"); + log.info("i"); + log.warn("w"); + log.error("e"); + + expect(logSpy.mock.calls.length).toBe(0); + expect(warnSpy.mock.calls.length).toBe(1); + expect(errorSpy.mock.calls.length).toBe(1); + }); + + it("level=error drops everything except error", () => { + const log = createConsoleLogger("error"); + log.debug("d"); + log.info("i"); + log.warn("w"); + log.error("e"); + + expect(logSpy.mock.calls.length).toBe(0); + expect(warnSpy.mock.calls.length).toBe(0); + expect(errorSpy.mock.calls.length).toBe(1); + }); + + it("default level is info", () => { + const log = createConsoleLogger(); + log.debug("d"); + log.info("i"); + + expect(logSpy.mock.calls.length).toBe(1); + expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] i"); + }); + }); + + describe("meta formatting", () => { + it("appends JSON-stringified meta when provided", () => { + const log = createConsoleLogger("info"); + log.info("hello", { a: 1, b: "two" }); + + expect(logSpy.mock.calls[0]?.[0]).toBe('[INFO] hello {"a":1,"b":"two"}'); + }); + + it("emits message only when meta is omitted", () => { + const log = createConsoleLogger("info"); + log.info("plain"); + + expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] plain"); + }); + + it("does not invoke JSON.stringify when level is filtered out", () => { + const log = createConsoleLogger("info"); + // A getter that throws would be invoked by JSON.stringify if the + // logger built the meta string before the level check. We rely on + // the call-site `isLevelEnabled` gate plus the internal `shouldLog` + // short-circuit to prevent that. + const trap = { + get problem() { + throw new Error("meta should not be stringified when level is filtered"); + }, + }; + // Should not throw — debug is below the info threshold. + log.debug("trap", trap as unknown as Record); + expect(logSpy.mock.calls.length).toBe(0); + }); + }); + + describe("isLevelEnabled", () => { + const cases: ReadonlyArray<{ + threshold: LogLevel; + enabled: ReadonlyArray; + disabled: ReadonlyArray; + }> = [ + { + threshold: "error", + enabled: ["error"], + disabled: ["warn", "info", "debug"], + }, + { + threshold: "warn", + enabled: ["error", "warn"], + disabled: ["info", "debug"], + }, + { + threshold: "info", + enabled: ["error", "warn", "info"], + disabled: ["debug"], + }, + { + threshold: "debug", + enabled: ["error", "warn", "info", "debug"], + disabled: [], + }, + ]; + + for (const { threshold, enabled, disabled } of cases) { + it(`level=${threshold} reports enabled levels correctly`, () => { + const log = createConsoleLogger(threshold); + for (const lvl of enabled) { + expect(log.isLevelEnabled?.(lvl)).toBe(true); + } + for (const lvl of disabled) { + expect(log.isLevelEnabled?.(lvl)).toBe(false); + } + }); + } + + it("call-site gate using `?? true` short-circuits expensive meta build at info level", () => { + // Mirrors the hot-path pattern used in renderOrchestrator: callers + // wrap meta construction in `if (log.isLevelEnabled?.('debug') ?? true)` + // so production (level=info) skips the work entirely. + const log = createConsoleLogger("info"); + let buildCount = 0; + const buildMeta = (): Record => { + buildCount += 1; + return { expensive: true }; + }; + + for (let i = 0; i < 100; i++) { + if (log.isLevelEnabled?.("debug") ?? true) { + log.debug("hot-loop", buildMeta()); + } + } + + expect(buildCount).toBe(0); + expect(logSpy.mock.calls.length).toBe(0); + }); + + it("call-site gate runs the meta builder when debug is enabled", () => { + const log = createConsoleLogger("debug"); + let buildCount = 0; + const buildMeta = (): Record => { + buildCount += 1; + return { iter: buildCount }; + }; + + for (let i = 0; i < 5; i++) { + if (log.isLevelEnabled?.("debug") ?? true) { + log.debug("loop", buildMeta()); + } + } + + expect(buildCount).toBe(5); + expect(logSpy.mock.calls.length).toBe(5); + }); + + it("custom logger without isLevelEnabled falls back to running the meta builder (`?? true`)", () => { + // A user-provided logger that doesn't implement isLevelEnabled — the + // call-site fallback must preserve the prior behavior of always + // building meta (so we don't silently drop diagnostics for them). + const calls: Array<{ msg: string; meta?: Record }> = []; + const customLog: ProducerLogger = { + error: (msg, meta) => calls.push({ msg, meta }), + warn: (msg, meta) => calls.push({ msg, meta }), + info: (msg, meta) => calls.push({ msg, meta }), + debug: (msg, meta) => calls.push({ msg, meta }), + }; + + let buildCount = 0; + const buildMeta = (): Record => { + buildCount += 1; + return { i: buildCount }; + }; + + for (let i = 0; i < 3; i++) { + if (customLog.isLevelEnabled?.("debug") ?? true) { + customLog.debug("evt", buildMeta()); + } + } + + expect(buildCount).toBe(3); + expect(calls).toHaveLength(3); + expect(calls[0]?.msg).toBe("evt"); + expect(calls[0]?.meta).toEqual({ i: 1 }); + }); + }); + + describe("defaultLogger", () => { + it("is a singleton at level=info", () => { + defaultLogger.info("default-info"); + defaultLogger.debug("default-debug"); + + expect(logSpy.mock.calls.length).toBe(1); + expect(logSpy.mock.calls[0]?.[0]).toBe("[INFO] default-info"); + }); + + it("exposes isLevelEnabled gating debug at info threshold", () => { + expect(defaultLogger.isLevelEnabled?.("info")).toBe(true); + expect(defaultLogger.isLevelEnabled?.("debug")).toBe(false); + }); + }); +}); diff --git a/packages/producer/src/logger.ts b/packages/producer/src/logger.ts index 09a633470..d0fa8b77f 100644 --- a/packages/producer/src/logger.ts +++ b/packages/producer/src/logger.ts @@ -15,6 +15,26 @@ export interface ProducerLogger { warn(message: string, meta?: Record): void; info(message: string, meta?: Record): void; debug(message: string, meta?: Record): void; + + /** + * Optional fast level check used to skip expensive metadata construction + * at the call site. When the call site needs to build a non-trivial meta + * object (e.g. snapshot a struct, format numbers, run `Array.find` over + * scene state) just to attach to a debug log, gate it with this method: + * + * ```ts + * if (log.isLevelEnabled?.("debug") ?? true) { + * const meta = buildExpensiveMeta(); + * log.debug("hot-path event", meta); + * } + * ``` + * + * The default coalescence (`?? true`) preserves today's behavior for + * loggers that omit this method — they keep building the meta object as + * before. Custom integrations (Pino, Winston, structured loggers) should + * implement this to enable the optimization. + */ + isLevelEnabled?(level: LogLevel): boolean; } const LOG_LEVEL_PRIORITY: Record = { @@ -59,6 +79,9 @@ export function createConsoleLogger(level: LogLevel = "info"): ProducerLogger { console.log(`[DEBUG] ${message}${formatMeta(meta)}`); } }, + isLevelEnabled(msgLevel) { + return shouldLog(msgLevel); + }, }; } diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index 308bb85fd..36911bd1c 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/packages/producer/src/services/renderOrchestrator.ts @@ -1972,7 +1972,27 @@ export async function executeRenderJob( (t) => i >= t.startFrame && i <= t.endFrame, ); - if (i % 30 === 0) { + // Per-frame debug snapshot (every 30 frames). The meta object + // requires `Array.find` over `stackingInfo` plus a number-format + // and conditional struct allocation — non-trivial work to do + // every 30 frames in the encode hot loop. Gate the entire block + // on the logger's level check so production runs (level=info) + // pay nothing. + // + // Audit note (PR #383 review): this is the only per-frame log + // site in the streaming HDR encode loop that constructs + // non-trivial metadata. The `[diag]` log.info calls inside + // compositeToBuffer (compositeToBuffer plan, hdr layer blit, + // dom layer blit, compositeToBuffer end) are already gated by + // `shouldLog = debugDumpEnabled && debugFrameIndex >= 0`, where + // debugDumpEnabled is driven by KEEP_TEMP=1 — strictly stricter + // than an isLevelEnabled check. The HDR blit error-path + // log.debugs only fire on caught failures, not on the happy + // path. Any new per-frame log site that builds meta should + // follow the same `if (log.isLevelEnabled?.("level") ?? true)` + // pattern (or stay behind `shouldLog`) so production stays + // allocation-free in the hot loop. + if (i % 30 === 0 && (log.isLevelEnabled?.("debug") ?? true)) { const hdrEl = stackingInfo.find((e) => e.isHdr); log.debug("[Render] HDR layer composite frame", { frame: i,