webavatar-core/docs/LOGGING.md

Debug logging

An ephemeral, in-memory debug-logging system: a shared Logger contract other code (session orchestration today; the humanoid package, analytics.ts, and future project surfaces potentially) can call into, plus a browser-side debug panel that shows entries live, filterable by category and level.

This is not analytics. ANALYTICS.md is a permanent, SQLite-backed record of business data (sessions/messages/tool-calls/events), written to disk, meant to be queried later. This system is the opposite on every axis: nothing is ever persisted, it exists purely to help a developer see what's happening in a live session, and a debug.log entry is explicitly never routed through AnalyticsRecorder (see session.spec.ts's regression test for this).

The contract

packages/core/src/logger.ts (exported from the package root '.') defines LogLevel (debug | info | warn | error), LogEntry { level, category, message, data?, timestamp }, and the Logger interface (debug/info/warn/error(category, message, data?)). category is an intentionally open string, never a closed enum — a package like humanoid's eye sub-package owns its own namespace (e.g. "humanoid.eye") without core needing to know about it ahead of time, the same "no registration step" rule as the package system itself (see ARCHITECTURE.md's "Optional packages").

Server side

packages/core/src/server/logger.ts's createLogger(onEntry?, options?) (exported from './server') builds a Logger that mirrors every call to the matching console.* method (visible in plain stdout/container logs with zero setup) and, if given, also invokes onEntry synchronously. options.logMessages (default true) controls only whether the messages category participates in that console mirror — see below.

RealtimeSession (session.ts) — the one object every session event in both directions already funnels through (see REALTIME_SESSION.md's connection flow) — owns one such logger per connection, wired so onEntry forwards to its own browserSocket as a debug.log ServerEvent, gated by a debugSubscribed flag. Because each RealtimeSession instance owns exactly one browser connection, this scoping is structural, not filtered: there's no session-lookup or broadcast step, so one session's logs can't reach another session's browser by construction (see session.spec.ts's two-concurrent-sessions test).

Logger calls are added at existing hook points — the same "attach where the plumbing already exists" approach ANALYTICS.md describes — covering session lifecycle (start() success/failure, close()), tool-call start/unknown-tool/timeout/completion, and WS-level protocol errors (malformed JSON, binary frames, a message sent before session.start). Deliberately not added on input_audio.chunk/output_audio.chunk — high-volume binary blobs, not debug material.

Conversation content, under its own messages category. Unlike the rest of this system, this one intentionally does carry conversation content — the system instructions (once, on session start) and the full text of every user/assistant message — precisely so a developer can see the whole conversation, including the system prompt, while debugging a live session. It reuses the exact points AnalyticsRecorder.messageLogged already hooks (typed input_text.send, a voice user transcript, the assembled assistant transcript on transcript.done) rather than the raw transcript.delta stream — one entry per complete message, not one per chunk. Each entry's data is { role: 'system' | 'user' | 'assistant', text }.

Because createLogger's console mirror otherwise runs for every category unconditionally (see above), full conversation text — including the system prompt — would always reach server stdout/container logs, every session, regardless of whether any browser is subscribed to debug.log at all. That's a different sensitivity tier than the rest of this system's operational logging, closer to what ANALYTICS_LOG_MESSAGES gates independently in analytics.ts. DEBUG_LOG_MESSAGES (config.debug.messages, default true) is the equivalent toggle here: set it to false and createLogger skips the console mirror specifically for the messages category, while every other category is unaffected. This only controls the console/stdout copy — onEntry (browser forwarding to a subscribed debug panel) still always fires either way, since that path is already independently gated by debugSubscribed (dev/DEBUG_ACCESS_KEY, see below). Worth setting to false in any deployment where server logs are shipped somewhere less trusted than the process's own stdout.

What's deliberately deferred: provider adapters (packages/core/src/server/provider.ts, packages/core/src/server/providers/openai.ts) are session-agnostic — they have no sessionId at all — so they don't get logger calls in this version. The one concrete case this leaves uninstrumented, providers/openai.ts's silently-dropped unmapped OpenAI events, is exactly the case REALTIME_SESSION.md's "OpenAI Realtime API gotcha" section already documents debugging by hand (a temporary console.debug + dev-server restart). Threading a Logger through the provider interface (plus the mock provider and their tests) is a reasonable fast-follow, not done here to keep this change reviewable.

Auth: debug.subscribe and DEBUG_ACCESS_KEY

Server-log forwarding rides the same realtime WebSocket connection as everything else, as a new pair of protocol events (protocol.ts):

• Client → server: debug.subscribe { key?: string }
• Server → client: debug.subscribe.result { ok, reason? }, debug.log (spreads LogEntry)

This deliberately does not reuse REALTIME_TOKEN_SECRET/the session token: that token proves "you got this from our server a moment ago," which every ordinary visitor to a public deployment gets automatically just by loading the page — it's not a developer credential. Server logs need a second, independent gate:

• Dev (isDev: true, passed as a literal from the ./vite dev plugin — one of the two composition roots that call createRealtimeRuntime, see ARCHITECTURE.md): every connection starts already subscribed. No debug.subscribe needed at all.
• Prod (isDev: false, passed as a literal from apps/template/server.js — the other composition root, into the same shared createRealtimeRuntime factory, packages/core/src/server/index.ts): a connection starts unsubscribed. The browser must send debug.subscribe { key } with a key matching DEBUG_ACCESS_KEY, verified by verifyDebugAccessKey() (timing-safe comparison, reusing tokens.ts's timingSafeCompare helper). DEBUG_ACCESS_KEY is read directly from process.env at comparison time, same lazy pattern as REALTIME_TOKEN_SECRET, but a deliberately separate secret with its own blast radius — see CONFIGURATION.md. Unset in prod means the feature is fully off for everyone — not presence-checked in loadConfig()'s fail-fast validation, since that's an intentional, valid state, not a misconfiguration.

debug.subscribe is handled unconditionally in handleBrowserMessage — alongside session.start/session.end, before the "must be active" gate — so a browser can subscribe before, during, or independent of an active session, and the message is never mistakenly forwarded to the upstream provider.

Client side

There's no ambient/shared realtime client anywhere in this codebase — each page (e.g. /demo/realtime) constructs its own ResilientRealtimeClient ad hoc. So the client side splits into two independent pieces:

• packages/core/src/client/logger.ts (exported from './client') — an ambient client-side logger. clientLogger (any browser code, with or without a realtime connection, can call clientLogger.warn('ws', ...)) and debugLogStore (a hand-rolled, bounded (~500-entry) ring buffer with a Svelte-store-compatible subscribe, the same idiom as @webavatar/webavatar-humanoid/client's avatar-state.ts (deriveAvatarState) — no svelte/store import anywhere in this repo, and this doesn't start one) always exist, regardless of any client.
• packages/core/src/client/server-log-forwarder.ts (exported from './client') — opt-in per page. attachServerLogForwarding(client, { isDev }) takes a structurally-typed client (same idiom as tool-dispatcher.ts's ToolDispatchClient) and returns a ServerLogForwarder: it listens for debug.log (pushing into the same shared buffer, tagged source: 'server') and debug.subscribe.result, and exposes subscribeWithKey(key) for the prod flow.

Reconnects: ResilientRealtimeClient reconnecting creates a brand-new server-side RealtimeSession (fresh sessionId, fresh unsubscribed state — see REALTIME_SESSION.md's "Resilience"). attachServerLogForwarding remembers the last key that worked and resends it on every transition to 'open', not just the first — otherwise forwarding would silently and permanently stop after any dropped connection.

DebugPanel.svelte (apps/template/src/lib/client/, app-owned — importing @webavatar/webavatar-core/client for the logger/store pieces it needs, not /demo — see below) renders debugLogStore unconditionally (so the ambient client-side buffer is always visible) and, given an optional forwarder prop, a subscription-status badge plus a key-entry field when in prod and not yet subscribed.

Where the panel lives, and why it's shippable in prod

Unlike /demo/**, which ARCHITECTURE.md frames as dev-only-gated verification scaffolding (404s via +layout.server.ts when !dev), DebugPanel.svelte lives in apps/template/src/lib/client/ — app-owned code that consumes @webavatar/webavatar-core/client for clientLogger/debugLogStore, shipped in the app's production bundle the same as the rest of apps/template/src/lib/client/. The key-based auth above, not route removal, is what protects server-log visibility in prod; the panel's client-side-only view has nothing sensitive to gate at all. apps/template/src/routes/demo/realtime/+page.svelte is simply one caller of it (wired to its own client, the same way it's already a caller of ResilientRealtimeClient); a branched project mounts <DebugPanel forwarder={...} /> the same way, wherever it has a client.

What's deliberately not built yet

• Provider-level logging (see above).
• Flood control on the forwarding path — a chatty logger.debug() call site could in principle spam a subscribed browser's WS at an unbounded rate. Acceptable for a v1 developer tool; this shares the same connection as real session traffic, so a future version might want batching/throttling.
• A keyboard shortcut to toggle the panel — v1 is a visible floating button only, to avoid introducing global keydown handling (a second brand-new UI pattern for this repo) without a stated need for it.
• Log export/copy, and any cross-session or whole-server-process log view (by design — see "The hook point" above).

Verifying changes

• npm run check / npm run lint.
• npm run test:unit — logger.spec.ts (server: console mirroring, verifyDebugAccessKey, safeSerialize; client: ring-buffer bounding, store semantics), the extended session.spec.ts (dev auto-forward, prod key gating, debug.subscribe before session.start, never reaching AnalyticsRecorder, and the cross-session-isolation test), server-log-forwarder.spec.ts (dev/prod state machine, reconnect resend), and DebugPanel.svelte.spec.ts (the first .svelte.spec.ts in this repo — kept smoke-level: mount, toggle, filter).
• Live smoke test: npm run dev, open /demo/realtime, click the debug-log toggle in the bottom-right corner, connect a session — server-side entries (session start, a tool call from the demo project's registered tools) should appear live with no manual subscribe step, since dev is frictionless.
• Prod-gating check: this template has no in-repo production page to click through the key-gated flow live (/demo/realtime is itself dev-only-gated, and the root page has no realtime client at all) — that path is covered by session.spec.ts's prod-mode tests and server-log-forwarder.spec.ts instead. To eyeball the key-entry UI itself, temporarily pass isDev: false to attachServerLogForwarding on the demo page, reload, and confirm the key field appears and gates forwarding; revert afterward.