diff --git a/.env.example b/.env.example index 8f7f1ce..0120741 100644 --- a/.env.example +++ b/.env.example @@ -51,3 +51,20 @@ REALTIME_TOKEN_SECRET= # TTL for the short-lived token minted by POST /api/realtime/session. # REALTIME_TOKEN_TTL_MS=60000 + +# --- Debug logging (see docs/LOGGING.md) --- + +# Shared secret a browser must present (via the debug panel's key field) to +# receive this app's server-side debug logs in production. Separate from +# REALTIME_TOKEN_SECRET on purpose — a different blast radius if leaked. +# In dev, forwarding is always on and this is ignored entirely. Leave unset +# in prod to disable server-log forwarding for everyone (the default). +# Generate one with: node -e "console.log(require('crypto').randomBytes(32).toString('hex'))" +# DEBUG_ACCESS_KEY= + +# Set to false to stop the `messages` log category (full conversation text, +# including the system prompt) from mirroring to console/stdout — useful if +# server logs are shipped somewhere less trusted than the process's own +# stdout. Independent of DEBUG_ACCESS_KEY: the debug panel itself is +# unaffected either way, since that path is already key-gated in prod. +# DEBUG_LOG_MESSAGES=true diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 9103c61..0eac51d 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -38,5 +38,6 @@ Routes (`src/routes/`) stay thin and delegate into these — a route file is glu | Analytics recording (sessions, messages, tool calls, errors) to a local SQLite database | [ANALYTICS.md](ANALYTICS.md) | | Configuration (env vars, validation, the core/project split for persona content) | [CONFIGURATION.md](CONFIGURATION.md) | | `humanoid` package — avatar-state derivation and animation-channel composition for humanoid avatars | [HUMANOID.md](HUMANOID.md) | +| Ephemeral, in-memory debug/logging system (open categories, level filtering, session-scoped WS forwarding to a client debug panel) — distinct from analytics | [LOGGING.md](LOGGING.md) | Add a row here (and a corresponding doc) for each new subsystem as it's built — see the "Documentation" section in [AGENTS.md](../AGENTS.md) for when and how. diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index 792501e..bdafdd0 100644 --- a/docs/CONFIGURATION.md +++ b/docs/CONFIGURATION.md @@ -11,6 +11,7 @@ interface AppConfig { openaiApiKey: string; // only required (and only meaningful) when realtimeProvider is 'openai' analytics: AnalyticsConfig; // { enabled, dbPath, messages, toolCalls, events } session: SessionRuntimeConfig; // { modelOverride?, defaultVoice?, clientToolTimeoutMs, tokenTtlMs } + debug: DebugConfig; // { messages } } ``` @@ -33,6 +34,8 @@ interface AppConfig { | `SESSION_DEFAULT_VOICE` | unset — provider picks | no | | `CLIENT_TOOL_TIMEOUT_MS` | `10000` | no | | `REALTIME_TOKEN_TTL_MS` | `60000` | no | +| `DEBUG_ACCESS_KEY` | unset (server-log forwarding off) | no — see below and [LOGGING.md](LOGGING.md) | +| `DEBUG_LOG_MESSAGES` | `true` | no — see below and [LOGGING.md](LOGGING.md) | Booleans accept exactly `"true"`/`"false"`; anything else (if the var is set at all) is a validation error. Integers are validated for range where one applies (e.g. `PORT` must be `1–65535`). @@ -44,6 +47,10 @@ This means `npm run dev` now requires a fully-populated `.env` to start at all `REALTIME_TOKEN_SECRET` is a deliberate partial exception: `loadConfig()` checks it's _present_ (so a missing secret is caught at the same startup point as everything else) but does not store its value on `AppConfig` — `tokens.ts` remains the sole reader of the actual secret, reading `process.env` directly and lazily, exactly as before. This is what keeps `tokens.spec.ts`'s existing pattern of mutating `process.env.REALTIME_TOKEN_SECRET` per test working unchanged. +`DEBUG_ACCESS_KEY` goes further still: it isn't even presence-checked here. Unlike every other var in the table above, leaving it unset is a valid, intentional deployment state — the debug panel's server-log forwarding is simply off for everyone in prod — not a misconfiguration worth failing loudly about. `src/lib/server/core/logger.ts`'s `verifyDebugAccessKey` is the sole reader, same lazy-`process.env` pattern as `REALTIME_TOKEN_SECRET`, but a deliberately separate secret — see [LOGGING.md](LOGGING.md). + +`DEBUG_LOG_MESSAGES` is not a secret, so it doesn't follow either of those two exceptions — it's presence-checked and validated like any other boolean (`ANALYTICS_ENABLED`, etc.) and its value (`config.debug.messages`) flows through `AppConfig` normally. It gates a narrower thing than `DEBUG_ACCESS_KEY`: not whether the debug panel can see a session's logs at all, but whether the `messages` category (full conversation content) additionally gets mirrored to server console/stdout unconditionally. See [LOGGING.md](LOGGING.md). + ## The `vite.config.ts` / Vitest gotcha **Do not** move a throwing, env-validating call to `vite.config.ts`'s top level, and don't have it build an already-resolved session-defaults object either. Both Vitest projects in `vite.config.ts`'s `test.projects` use `extends: './vite.config.ts'`, so this file's top-level code — and any plugin `configureServer` hook — runs on every `npm run test:unit`, not just `npm run dev`. `dev-plugin.ts`'s `configureServer` already has to guard itself with `if (process.env.VITEST) return` for exactly this reason. diff --git a/docs/LOGGING.md b/docs/LOGGING.md new file mode 100644 index 0000000..d1685b5 --- /dev/null +++ b/docs/LOGGING.md @@ -0,0 +1,66 @@ +# 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](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 + +`src/lib/core/logger.ts` 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](ARCHITECTURE.md)'s "Optional packages"). + +## Server side + +`src/lib/server/core/logger.ts`'s `createLogger(onEntry?, options?)` 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 (`provider.ts`, `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 `dev-plugin.ts` — that file only ever runs in dev): every connection starts already subscribed. No `debug.subscribe` needed at all. +- **Prod** (`isDev: false`, passed as a literal from `server.js` — that file only ever runs in prod): 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](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: + +- **`src/lib/client/core/logger.ts`** — 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 `$lib/client/humanoid/avatar-state.ts`'s `deriveAvatarState` — no `svelte/store` import anywhere in this repo, and this doesn't start one) always exist, regardless of any client. +- **`src/lib/client/core/server-log-forwarder.ts`** — _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` (`src/lib/client/core`, **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](ARCHITECTURE.md) frames as dev-only-gated verification scaffolding (404s via `+layout.server.ts` when `!dev`), `DebugPanel.svelte` lives in `src/lib/client/core/` — the same production-shippable tier as `client.ts`/`resilient-client.ts`. 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. `/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 `` 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. diff --git a/docs/REALTIME_SESSION.md b/docs/REALTIME_SESSION.md index 211e167..dcae9b4 100644 --- a/docs/REALTIME_SESSION.md +++ b/docs/REALTIME_SESSION.md @@ -101,8 +101,10 @@ Both call the same [`handleRealtimeUpgrade`](../src/lib/server/core/ws-handler.t See [`protocol.ts`](../src/lib/core/protocol.ts) for the authoritative, current list — this is a summary, not a copy to keep in sync by hand. -- **Client → server**: `session.start`, `input_audio.chunk`, `input_audio.commit`, `input_text.send`, `response.cancel`, `session.end` -- **Server → client**: `session.ready`, `output_audio.chunk`, `output_audio.done`, `transcript.delta`, `transcript.done`, `response.done`, `error`, `session.closed` +- **Client → server**: `session.start`, `input_audio.chunk`, `input_audio.commit`, `input_text.send`, `response.cancel`, `session.end`, `debug.subscribe` +- **Server → client**: `session.ready`, `output_audio.chunk`, `output_audio.done`, `transcript.delta`, `transcript.done`, `response.done`, `error`, `session.closed`, `debug.subscribe.result`, `debug.log` + +`debug.subscribe`/`debug.subscribe.result`/`debug.log` are a separate concern from the rest of this vocabulary — ephemeral developer debug-log forwarding, not session content. See [LOGGING.md](LOGGING.md). ## OpenAI Realtime API gotcha (verified live, Aug 2026) diff --git a/server.js b/server.js index 2d49aa4..9703214 100644 --- a/server.js +++ b/server.js @@ -38,7 +38,15 @@ server.on('upgrade', (req, socket, head) => { provider, defaults, recorder, - clientToolTimeoutMs: config.session.clientToolTimeoutMs + clientToolTimeoutMs: config.session.clientToolTimeoutMs, + // This entrypoint only ever runs in production (see dev-plugin.ts for + // the dev side) — debug-log forwarding here requires a valid + // DEBUG_ACCESS_KEY on each connection. See docs/LOGGING.md. + isDev: false, + // Gates the `messages` category's console mirror only — browser + // forwarding above is unaffected. See DEBUG_LOG_MESSAGES in + // docs/CONFIGURATION.md. + logMessages: config.debug.messages }); }); diff --git a/src/lib/client/core/DebugPanel.svelte b/src/lib/client/core/DebugPanel.svelte new file mode 100644 index 0000000..cff6b78 --- /dev/null +++ b/src/lib/client/core/DebugPanel.svelte @@ -0,0 +1,300 @@ + + + + +{#if open} +
+
+ Debug log + {statusLabel} + +
+ + {#if forwarder && !forwarder.isDev && !forwarderState?.subscribed} +
+ + + {#if forwarderState?.lastError} + {forwarderState.lastError} + {/if} +
+ {/if} + +
+ + {#each LEVELS as level (level)} + + {/each} +
+ + +
+{/if} + + diff --git a/src/lib/client/core/DebugPanel.svelte.spec.ts b/src/lib/client/core/DebugPanel.svelte.spec.ts new file mode 100644 index 0000000..35a86a6 --- /dev/null +++ b/src/lib/client/core/DebugPanel.svelte.spec.ts @@ -0,0 +1,59 @@ +import { beforeEach, describe, expect, it } from 'vitest'; +import { render } from 'vitest-browser-svelte'; +import { clearLogs, clientLogger } from './logger.js'; +import DebugPanel from './DebugPanel.svelte'; + +beforeEach(() => { + clearLogs(); +}); + +describe('DebugPanel', () => { + it('renders the toggle button with the current entry count, closed by default', async () => { + clientLogger.info('a', 'one'); + clientLogger.info('b', 'two'); + + const screen = await render(DebugPanel, { forwarder: null }); + + expect(screen.container.textContent).toContain('Debug log (2)'); + // Closed: entries shouldn't be in the DOM yet. + expect(screen.container.textContent).not.toContain('one'); + }); + + it('shows local-only status and both entries once opened, with no forwarder given', async () => { + clientLogger.info('a', 'one'); + clientLogger.warn('b', 'two'); + + const screen = await render(DebugPanel, { forwarder: null }); + await screen.getByRole('button', { name: /debug log/i }).click(); + + expect(screen.container.textContent).toContain('local only'); + expect(screen.container.textContent).toContain('one'); + expect(screen.container.textContent).toContain('two'); + // No forwarder means nothing to subscribe to — no key field. + expect(screen.container.querySelector('input[type="password"]')).toBeNull(); + }); + + it('filters entries by category', async () => { + clientLogger.info('alpha', 'from alpha'); + clientLogger.info('beta', 'from beta'); + + const screen = await render(DebugPanel, { forwarder: null }); + await screen.getByRole('button', { name: /debug log/i }).click(); + await screen.getByPlaceholder('Filter by category…').fill('alpha'); + + expect(screen.container.textContent).toContain('from alpha'); + expect(screen.container.textContent).not.toContain('from beta'); + }); + + it('hides entries at a level whose filter checkbox is unchecked', async () => { + clientLogger.debug('a', 'a debug message'); + clientLogger.error('a', 'an error message'); + + const screen = await render(DebugPanel, { forwarder: null }); + await screen.getByRole('button', { name: /debug log/i }).click(); + await screen.getByRole('checkbox', { name: 'debug' }).click(); + + expect(screen.container.textContent).not.toContain('a debug message'); + expect(screen.container.textContent).toContain('an error message'); + }); +}); diff --git a/src/lib/client/core/logger.spec.ts b/src/lib/client/core/logger.spec.ts new file mode 100644 index 0000000..08e9691 --- /dev/null +++ b/src/lib/client/core/logger.spec.ts @@ -0,0 +1,94 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { clearLogs, clientLogger, debugLogStore, pushLogEntry } from './logger.js'; + +beforeEach(() => { + clearLogs(); + for (const level of ['debug', 'info', 'warn', 'error'] as const) { + vi.spyOn(console, level).mockImplementation(() => {}); + } +}); + +function currentEntries(): unknown[] { + let snapshot: unknown[] = []; + const unsubscribe = debugLogStore.subscribe((entries) => { + snapshot = entries; + }); + unsubscribe(); + return snapshot; +} + +describe('clientLogger', () => { + it('pushes a client-tagged entry into the shared buffer', () => { + clientLogger.warn('ws', 'reconnecting', { attempt: 1 }); + const entries = currentEntries(); + expect(entries).toEqual([ + expect.objectContaining({ + level: 'warn', + category: 'ws', + message: 'reconnecting', + data: { attempt: 1 }, + source: 'client' + }) + ]); + }); +}); + +describe('pushLogEntry', () => { + it('defaults to tagging entries as server-sourced', () => { + pushLogEntry({ level: 'info', category: 'session', message: 'started', timestamp: 123 }); + expect(currentEntries()).toEqual([expect.objectContaining({ source: 'server' })]); + }); + + it('accepts an explicit source', () => { + pushLogEntry({ level: 'info', category: 'x', message: 'y', timestamp: 1 }, 'client'); + expect(currentEntries()).toEqual([expect.objectContaining({ source: 'client' })]); + }); +}); + +describe('debugLogStore', () => { + it('delivers the current buffer immediately on subscribe', () => { + clientLogger.info('a', 'one'); + const received: unknown[][] = []; + debugLogStore.subscribe((entries) => received.push(entries)); + expect(received).toHaveLength(1); + expect(received[0]).toHaveLength(1); + }); + + it('notifies subscribers on every subsequent push', () => { + const received: unknown[][] = []; + debugLogStore.subscribe((entries) => received.push(entries)); + clientLogger.info('a', 'one'); + clientLogger.info('b', 'two'); + // Initial delivery (empty) + one per push. + expect(received).toHaveLength(3); + expect(received.at(-1)).toHaveLength(2); + }); + + it('stops notifying after unsubscribe', () => { + const received: unknown[][] = []; + const unsubscribe = debugLogStore.subscribe((entries) => received.push(entries)); + unsubscribe(); + clientLogger.info('a', 'one'); + expect(received).toHaveLength(1); // only the initial delivery + }); + + it('caps the buffer at 500 entries, dropping the oldest first', () => { + for (let i = 0; i < 510; i++) { + clientLogger.debug('flood', `entry ${i}`); + } + const entries = currentEntries() as { message: string }[]; + expect(entries).toHaveLength(500); + expect(entries[0].message).toBe('entry 10'); + expect(entries.at(-1)?.message).toBe('entry 509'); + }); +}); + +describe('clearLogs', () => { + it('empties the buffer and notifies subscribers', () => { + clientLogger.info('a', 'one'); + const received: unknown[][] = []; + debugLogStore.subscribe((entries) => received.push(entries)); + clearLogs(); + expect(received.at(-1)).toEqual([]); + }); +}); diff --git a/src/lib/client/core/logger.ts b/src/lib/client/core/logger.ts new file mode 100644 index 0000000..f1aef31 --- /dev/null +++ b/src/lib/client/core/logger.ts @@ -0,0 +1,70 @@ +import type { LogEntry, LogLevel, Logger } from '../../core/logger.js'; + +/** A `LogEntry` tagged with where it came from, for display in `DebugPanel.svelte`. */ +export interface DisplayLogEntry extends LogEntry { + source: 'client' | 'server'; +} + +const MAX_ENTRIES = 500; + +let entries: DisplayLogEntry[] = []; +const subscribers = new Set<(entries: DisplayLogEntry[]) => void>(); + +function notify(): void { + for (const run of subscribers) run(entries); +} + +function push(entry: DisplayLogEntry): void { + entries = entries.length >= MAX_ENTRIES ? [...entries.slice(1), entry] : [...entries, entry]; + notify(); +} + +/** + * Feeds a server-forwarded `debug.log` entry into the same shared buffer the + * panel renders. Not for direct use by app code — call `clientLogger` for + * anything happening in the browser itself; this is exported specifically + * for `server-log-forwarder.ts`. + */ +export function pushLogEntry(entry: LogEntry, source: DisplayLogEntry['source'] = 'server'): void { + push({ ...entry, source }); +} + +function log(level: LogLevel, category: string, message: string, data?: unknown): void { + if (data === undefined) { + console[level](`[${category}] ${message}`); + } else { + console[level](`[${category}] ${message}`, data); + } + push({ level, category, message, data, timestamp: Date.now(), source: 'client' }); +} + +/** + * Ambient client-side logger — any browser code (with or without a realtime + * connection) can call this directly, e.g. `clientLogger.warn('ws', ...)`. + * Feeds the same shared buffer `DebugPanel.svelte` renders. + */ +export const clientLogger: Logger = { + debug: (category, message, data) => log('debug', category, message, data), + info: (category, message, data) => log('info', category, message, data), + warn: (category, message, data) => log('warn', category, message, data), + error: (category, message, data) => log('error', category, message, data) +}; + +/** + * Read-only, Svelte-store-compatible view of the shared log buffer (client + * entries plus anything forwarded from the server) — hand-rolled the same + * way as `$lib/client/humanoid/avatar-state.ts`'s `deriveAvatarState`; no + * `svelte/store` import anywhere in this repo, and this doesn't start one. + */ +export const debugLogStore = { + subscribe(run: (entries: DisplayLogEntry[]) => void): () => void { + subscribers.add(run); + run(entries); + return () => subscribers.delete(run); + } +}; + +export function clearLogs(): void { + entries = []; + notify(); +} diff --git a/src/lib/client/core/server-log-forwarder.spec.ts b/src/lib/client/core/server-log-forwarder.spec.ts new file mode 100644 index 0000000..29a3e84 --- /dev/null +++ b/src/lib/client/core/server-log-forwarder.spec.ts @@ -0,0 +1,179 @@ +import { beforeEach, describe, expect, it } from 'vitest'; +import type { ClientEvent, ServerEvent } from '../../core/protocol.js'; +import { clearLogs, debugLogStore } from './logger.js'; +import { + attachServerLogForwarding, + type ServerLogForwardingClient +} from './server-log-forwarder.js'; + +type ConnState = 'connecting' | 'open' | 'reconnecting' | 'closed'; + +/** Minimal stand-in for a realtime client — only what attachServerLogForwarding touches. */ +class FakeClient implements ServerLogForwardingClient { + sent: ClientEvent[] = []; + private eventHandler: ((event: ServerEvent) => void) | null = null; + private stateHandler: ((state: ConnState) => void) | null = null; + + send(event: ClientEvent): void { + this.sent.push(event); + } + + on(handler: (event: ServerEvent) => void): () => void { + this.eventHandler = handler; + return () => { + this.eventHandler = null; + }; + } + + onConnectionState(handler: (state: ConnState) => void): () => void { + this.stateHandler = handler; + return () => { + this.stateHandler = null; + }; + } + + /** Simulates a ServerEvent arriving from the (fake) relay. */ + emit(event: ServerEvent): void { + this.eventHandler?.(event); + } + + /** Simulates a connection-state transition, as ResilientRealtimeClient would report. */ + emitState(state: ConnState): void { + this.stateHandler?.(state); + } +} + +beforeEach(() => { + clearLogs(); +}); + +describe('attachServerLogForwarding', () => { + it('dev: starts subscribed with nothing sent', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: true }); + + let state: unknown; + forwarder.subscribe((s) => (state = s)); + + expect(state).toEqual({ subscribed: true, lastError: null }); + expect(client.sent).toEqual([]); + }); + + it('prod: starts unsubscribed', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + + let state: unknown; + forwarder.subscribe((s) => (state = s)); + + expect(state).toEqual({ subscribed: false, lastError: null }); + }); + + it('prod: subscribeWithKey sends debug.subscribe with the key', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + + forwarder.subscribeWithKey('my-key'); + + expect(client.sent).toEqual([{ type: 'debug.subscribe', key: 'my-key' }]); + }); + + it('prod: ignores subscribeWithKey in dev (nothing to subscribe to)', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: true }); + + forwarder.subscribeWithKey('anything'); + + expect(client.sent).toEqual([]); + }); + + it('prod: debug.subscribe.result{ok:true} marks the forwarder subscribed', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + const states: unknown[] = []; + forwarder.subscribe((s) => states.push(s)); + + forwarder.subscribeWithKey('my-key'); + client.emit({ type: 'debug.subscribe.result', ok: true }); + + expect(states.at(-1)).toEqual({ subscribed: true, lastError: null }); + }); + + it('prod: debug.subscribe.result{ok:false} records the failure reason', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + const states: unknown[] = []; + forwarder.subscribe((s) => states.push(s)); + + forwarder.subscribeWithKey('wrong-key'); + client.emit({ type: 'debug.subscribe.result', ok: false, reason: 'nope' }); + + expect(states.at(-1)).toEqual({ subscribed: false, lastError: 'nope' }); + }); + + it('pushes an incoming debug.log event into the shared client-side buffer, tagged server', () => { + const client = new FakeClient(); + attachServerLogForwarding(client, { isDev: true }); + + client.emit({ + type: 'debug.log', + level: 'info', + category: 'session', + message: 'hi', + timestamp: 1 + }); + + let entries: unknown[] = []; + debugLogStore.subscribe((e) => (entries = e)); + expect(entries).toEqual([ + expect.objectContaining({ category: 'session', message: 'hi', source: 'server' }) + ]); + }); + + it('prod: resends the remembered key on every reconnect, not just the first', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + + forwarder.subscribeWithKey('my-key'); + client.sent = []; // clear the initial subscribeWithKey send + + client.emitState('open'); + client.emitState('reconnecting'); + client.emitState('open'); + + expect(client.sent).toEqual([ + { type: 'debug.subscribe', key: 'my-key' }, + { type: 'debug.subscribe', key: 'my-key' } + ]); + }); + + it('prod: does not resend before any key has ever been provided', () => { + const client = new FakeClient(); + attachServerLogForwarding(client, { isDev: false }); + + client.emitState('open'); + + expect(client.sent).toEqual([]); + }); + + it('dev: never sends on reconnect (nothing to resend)', () => { + const client = new FakeClient(); + attachServerLogForwarding(client, { isDev: true }); + + client.emitState('open'); + + expect(client.sent).toEqual([]); + }); + + it('detach stops listening for further events and state changes', () => { + const client = new FakeClient(); + const forwarder = attachServerLogForwarding(client, { isDev: false }); + const states: unknown[] = []; + forwarder.subscribe((s) => states.push(s)); + + forwarder.detach(); + client.emit({ type: 'debug.subscribe.result', ok: true }); + + expect(states.at(-1)).toEqual({ subscribed: false, lastError: null }); + }); +}); diff --git a/src/lib/client/core/server-log-forwarder.ts b/src/lib/client/core/server-log-forwarder.ts new file mode 100644 index 0000000..5d252b6 --- /dev/null +++ b/src/lib/client/core/server-log-forwarder.ts @@ -0,0 +1,95 @@ +import type { ClientEvent, ServerEvent } from '../../core/protocol.js'; +import { pushLogEntry } from './logger.js'; + +/** + * The subset of `RealtimeClient`'s (or `ResilientRealtimeClient`'s) surface + * this needs — accepted structurally, same idiom as `ToolDispatchClient` / + * `AvatarStateSource`. `onConnectionState` is optional since bare + * `RealtimeClient` has no reconnect logic and therefore no such observable; + * without it, a dropped connection simply stops forwarding (there's nothing + * to reconnect to resubscribe on). + */ +export interface ServerLogForwardingClient { + send(event: ClientEvent): void; + on(handler: (event: ServerEvent) => void): () => void; + /** Mirrors `ResilientRealtimeClient`'s `ConnectionState` without importing it, to stay structural. */ + onConnectionState?( + handler: (state: 'connecting' | 'open' | 'reconnecting' | 'closed') => void + ): () => void; +} + +export interface ServerLogForwarderState { + subscribed: boolean; + lastError: string | null; +} + +export interface ServerLogForwarder { + readonly isDev: boolean; + /** Svelte-store-compatible: calls `run` immediately with the current value, then on every change. */ + subscribe(run: (state: ServerLogForwarderState) => void): () => void; + /** No-op in dev (forwarding is already automatic). In prod, sends `debug.subscribe` with this key. */ + subscribeWithKey(key: string): void; + /** Stops listening to the client. Does not close the client itself. */ + detach(): void; +} + +/** + * Wires a realtime client up to receive this session's own server-side debug + * logs — see docs/LOGGING.md. In dev, the server forwards automatically with + * no handshake, so this starts (and stays) subscribed with nothing sent. In + * prod, nothing is forwarded until `subscribeWithKey` succeeds. + * + * A reconnect (`ResilientRealtimeClient`) tears down and rebuilds the + * server-side session from scratch, with a fresh (unsubscribed) forwarding + * state — so in prod, the last key that worked is remembered and resent on + * every transition to `'open'`, not just the first, or forwarding would + * silently and permanently stop after any dropped connection. + */ +export function attachServerLogForwarding( + client: ServerLogForwardingClient, + opts: { isDev: boolean } +): ServerLogForwarder { + let state: ServerLogForwarderState = { subscribed: opts.isDev, lastError: null }; + let rememberedKey: string | null = null; + const subscribers = new Set<(state: ServerLogForwarderState) => void>(); + + function setState(next: ServerLogForwarderState): void { + state = next; + for (const run of subscribers) run(state); + } + + const stopEvents = client.on((event) => { + if (event.type === 'debug.log') { + pushLogEntry(event, 'server'); + return; + } + if (event.type === 'debug.subscribe.result') { + setState({ subscribed: event.ok, lastError: event.ok ? null : (event.reason ?? null) }); + } + }); + + const stopConnectionState = client.onConnectionState?.((connState) => { + if (connState === 'open' && !opts.isDev && rememberedKey) { + client.send({ type: 'debug.subscribe', key: rememberedKey }); + } + }); + + return { + isDev: opts.isDev, + subscribe(run) { + subscribers.add(run); + run(state); + return () => subscribers.delete(run); + }, + subscribeWithKey(key) { + if (opts.isDev) return; + rememberedKey = key; + client.send({ type: 'debug.subscribe', key }); + }, + detach() { + stopEvents(); + stopConnectionState?.(); + subscribers.clear(); + } + }; +} diff --git a/src/lib/core/logger.ts b/src/lib/core/logger.ts new file mode 100644 index 0000000..ecab9b9 --- /dev/null +++ b/src/lib/core/logger.ts @@ -0,0 +1,39 @@ +/** + * Ephemeral, in-memory debug-logging contract — shared across server and + * browser code, and by any package/project that wants to emit developer- + * facing debug output (see docs/LOGGING.md). Deliberately unrelated to + * `$lib/server/core/analytics.ts`: that module is a permanent record of + * business data (sessions/messages/tool-calls/events); this is a disposable + * debugging aid, never persisted to disk. + * + * `category` is an intentionally open string, not a closed union — packages + * like `humanoid` (and its `eye` sub-package) own their own namespace (e.g. + * `"humanoid.eye"`) without core needing to know about them ahead of time, + * the same "no registration step" rule as the package system itself (see + * docs/ARCHITECTURE.md's "Optional packages" section). + */ + +export type LogLevel = 'debug' | 'info' | 'warn' | 'error'; + +export interface LogEntry { + level: LogLevel; + category: string; + message: string; + data?: unknown; + timestamp: number; // epoch ms +} + +export interface Logger { + debug(category: string, message: string, data?: unknown): void; + info(category: string, message: string, data?: unknown): void; + warn(category: string, message: string, data?: unknown): void; + error(category: string, message: string, data?: unknown): void; +} + +/** Discards every call. Useful as a default so callers never need to null-check a `Logger`. */ +export const NOOP_LOGGER: Logger = { + debug() {}, + info() {}, + warn() {}, + error() {} +}; diff --git a/src/lib/core/protocol.ts b/src/lib/core/protocol.ts index 8b21a63..dd44fb5 100644 --- a/src/lib/core/protocol.ts +++ b/src/lib/core/protocol.ts @@ -8,6 +8,8 @@ * session orchestrator provider-agnostic. */ +import type { LogEntry } from './logger.js'; + export const REALTIME_WS_PATH = '/api/realtime/ws'; /** @@ -32,7 +34,11 @@ export type ClientEvent = // by the browser directly, since a turn can contain multiple parallel // tool calls and only the last one resolving should trigger this. | { type: 'response.trigger' } - | { type: 'session.end' }; + | { type: 'session.end' } + // Requests server-side debug-log forwarding on this connection — see + // docs/LOGGING.md. `key` is required in production (checked against + // DEBUG_ACCESS_KEY) and ignored in dev, where forwarding is automatic. + | { type: 'debug.subscribe'; key?: string }; export type RealtimeErrorCode = | 'auth_expired' @@ -50,4 +56,10 @@ export type ServerEvent = | { type: 'response.done' } | { type: 'tool.call'; callId: string; name: string; arguments: string } | { type: 'error'; code: RealtimeErrorCode; message: string } - | { type: 'session.closed'; reason: string }; + | { type: 'session.closed'; reason: string } + // Reply to a `debug.subscribe` request — see docs/LOGGING.md. + | { type: 'debug.subscribe.result'; ok: boolean; reason?: string } + // A single log entry forwarded from the server for this session only + // (never another session's) — spreads `LogEntry` since the wire payload + // *is* one, plus the `type` discriminant. + | ({ type: 'debug.log' } & LogEntry); diff --git a/src/lib/server/core/config.spec.ts b/src/lib/server/core/config.spec.ts index 790a146..50331b1 100644 --- a/src/lib/server/core/config.spec.ts +++ b/src/lib/server/core/config.spec.ts @@ -15,7 +15,8 @@ const ENV_KEYS = [ 'SESSION_MODEL', 'SESSION_DEFAULT_VOICE', 'CLIENT_TOOL_TIMEOUT_MS', - 'REALTIME_TOKEN_TTL_MS' + 'REALTIME_TOKEN_TTL_MS', + 'DEBUG_LOG_MESSAGES' ] as const; const REQUIRED_ENV = { @@ -72,6 +73,9 @@ describe('loadConfig', () => { defaultVoice: undefined, clientToolTimeoutMs: 10_000, tokenTtlMs: 60_000 + }, + debug: { + messages: true } }); }); @@ -94,7 +98,8 @@ describe('loadConfig', () => { SESSION_MODEL: 'custom-model', SESSION_DEFAULT_VOICE: 'alloy', CLIENT_TOOL_TIMEOUT_MS: '5000', - REALTIME_TOKEN_TTL_MS: '30000' + REALTIME_TOKEN_TTL_MS: '30000', + DEBUG_LOG_MESSAGES: 'false' }); const loadConfig = await freshLoadConfig(); @@ -114,6 +119,9 @@ describe('loadConfig', () => { defaultVoice: 'alloy', clientToolTimeoutMs: 5000, tokenTtlMs: 30000 + }, + debug: { + messages: false } }); }); @@ -162,6 +170,12 @@ describe('loadConfig', () => { expect(() => loadConfig()).toThrow(/ANALYTICS_ENABLED must be "true" or "false"/); }); + it('throws a descriptive error for an invalid DEBUG_LOG_MESSAGES value', async () => { + Object.assign(process.env, REQUIRED_ENV, { DEBUG_LOG_MESSAGES: 'yes' }); + const loadConfig = await freshLoadConfig(); + expect(() => loadConfig()).toThrow(/DEBUG_LOG_MESSAGES must be "true" or "false"/); + }); + it('throws a descriptive error for a non-integer value', async () => { Object.assign(process.env, REQUIRED_ENV, { PORT: 'not-a-number' }); const loadConfig = await freshLoadConfig(); diff --git a/src/lib/server/core/config.ts b/src/lib/server/core/config.ts index dabb35d..0f3d1cb 100644 --- a/src/lib/server/core/config.ts +++ b/src/lib/server/core/config.ts @@ -22,6 +22,17 @@ export interface SessionRuntimeConfig { tokenTtlMs: number; } +export interface DebugConfig { + /** + * Gates whether the `messages` debug-log category (full conversation + * content, including the system prompt — see docs/LOGGING.md) mirrors to + * console/stdout. Independent of `debug.subscribe`'s browser-forwarding + * gate (dev/`DEBUG_ACCESS_KEY`), which is unaffected either way — this + * only controls the *unconditional* server-log copy. + */ + messages: boolean; +} + export interface AppConfig { port: number; /** Which `RealtimeProvider` to construct — see `providers/index.ts`'s `selectProvider`. */ @@ -30,6 +41,7 @@ export interface AppConfig { openaiApiKey: string; analytics: AnalyticsConfig; session: SessionRuntimeConfig; + debug: DebugConfig; } let cached: AppConfig | null = null; @@ -50,6 +62,19 @@ let cached: AppConfig | null = null; * pattern of mutating `process.env.REALTIME_TOKEN_SECRET` per test to * exercise `mintSessionToken`/`verifySessionToken` against different * secrets — don't "simplify" this away. + * + * `DEBUG_ACCESS_KEY` (see `./logger.ts`'s `verifyDebugAccessKey` and + * docs/LOGGING.md) follows the same "never store the raw secret on + * `AppConfig`" pattern, but is a *stronger* exception: it's not even + * presence-checked here. Unlike `REALTIME_TOKEN_SECRET`, an unset + * `DEBUG_ACCESS_KEY` is a valid, intentional deployment state — the debug + * panel's server-log forwarding is simply disabled for everyone in prod — + * not a misconfiguration worth failing loudly about. + * + * `DEBUG_LOG_MESSAGES` (`debug.messages` below) is not a secret, so it *does* + * go through the normal fail-fast-validated path here, the same as + * `ANALYTICS_LOG_MESSAGES` — it just gates a different sink (the debug + * logger's console mirror) than that one does (the analytics DB). */ export function loadConfig(): AppConfig { if (cached) return cached; @@ -87,11 +112,15 @@ export function loadConfig(): AppConfig { tokenTtlMs: parseIntEnv('REALTIME_TOKEN_TTL_MS', 60_000, { min: 1 }, errors) }; + const debug: DebugConfig = { + messages: parseBoolEnv('DEBUG_LOG_MESSAGES', true, errors) + }; + if (errors.length > 0) { throw new Error(`Invalid configuration:\n${errors.map((e) => ` - ${e}`).join('\n')}`); } - cached = { port, realtimeProvider, openaiApiKey, analytics, session }; + cached = { port, realtimeProvider, openaiApiKey, analytics, session, debug }; return cached; } diff --git a/src/lib/server/core/dev-plugin.ts b/src/lib/server/core/dev-plugin.ts index 6bc8e4e..ea5e963 100644 --- a/src/lib/server/core/dev-plugin.ts +++ b/src/lib/server/core/dev-plugin.ts @@ -65,7 +65,15 @@ export function realtimeDevWsPlugin(options: RealtimeDevWsPluginOptions): Plugin provider, defaults, recorder, - clientToolTimeoutMs: config.session.clientToolTimeoutMs + clientToolTimeoutMs: config.session.clientToolTimeoutMs, + // This plugin only ever runs in dev (see the VITEST guard above), + // so this is a literal, not an env lookup — debug-log forwarding + // is frictionless here. See ../../../../server.js for the prod side. + isDev: true, + // Unlike isDev, this reads from config (not a literal) — a + // developer may still want DEBUG_LOG_MESSAGES=false locally, e.g. + // to rehearse prod-like log hygiene. See docs/LOGGING.md. + logMessages: config.debug.messages }); }); } diff --git a/src/lib/server/core/logger.spec.ts b/src/lib/server/core/logger.spec.ts new file mode 100644 index 0000000..c77fb18 --- /dev/null +++ b/src/lib/server/core/logger.spec.ts @@ -0,0 +1,129 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { createLogger, safeSerialize, verifyDebugAccessKey } from './logger.js'; + +describe('createLogger', () => { + it('mirrors every call to the matching console method', () => { + const spy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const logger = createLogger(); + logger.warn('ws', 'something happened', { detail: 1 }); + expect(spy).toHaveBeenCalledWith('[ws] something happened', { detail: 1 }); + spy.mockRestore(); + }); + + it('omits the data argument to console when none is given', () => { + const spy = vi.spyOn(console, 'info').mockImplementation(() => {}); + const logger = createLogger(); + logger.info('session', 'started'); + expect(spy).toHaveBeenCalledWith('[session] started'); + spy.mockRestore(); + }); + + it('invokes onEntry with a fully-populated LogEntry', () => { + vi.spyOn(console, 'debug').mockImplementation(() => {}); + const entries: unknown[] = []; + const logger = createLogger((entry) => entries.push(entry)); + logger.debug('tools', 'tool call started', { callId: 'abc' }); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + level: 'debug', + category: 'tools', + message: 'tool call started', + data: { callId: 'abc' } + }); + expect((entries[0] as { timestamp: number }).timestamp).toEqual(expect.any(Number)); + }); + + it('never calls onEntry for a different call site', () => { + vi.spyOn(console, 'error').mockImplementation(() => {}); + const onEntry = vi.fn(); + createLogger(onEntry).error('x', 'y'); + // A second, independent logger with no onEntry must not somehow share state. + createLogger().error('x', 'y'); + expect(onEntry).toHaveBeenCalledTimes(1); + }); + + it('still mirrors the messages category to console by default', () => { + const spy = vi.spyOn(console, 'info').mockImplementation(() => {}); + createLogger().info('messages', 'User message', { role: 'user', text: 'hi' }); + expect(spy).toHaveBeenCalledWith('[messages] User message', { role: 'user', text: 'hi' }); + spy.mockRestore(); + }); + + it('skips the console mirror for the messages category when logMessages is false', () => { + const spy = vi.spyOn(console, 'info').mockImplementation(() => {}); + createLogger(undefined, { logMessages: false }).info('messages', 'User message', { + role: 'user', + text: 'hi' + }); + expect(spy).not.toHaveBeenCalled(); + spy.mockRestore(); + }); + + it('leaves every other category mirrored to console when logMessages is false', () => { + const spy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + createLogger(undefined, { logMessages: false }).warn('ws', 'something happened'); + expect(spy).toHaveBeenCalledWith('[ws] something happened'); + spy.mockRestore(); + }); + + it('still invokes onEntry for the messages category when logMessages is false', () => { + vi.spyOn(console, 'info').mockImplementation(() => {}); + const entries: unknown[] = []; + const logger = createLogger((entry) => entries.push(entry), { logMessages: false }); + logger.info('messages', 'User message', { role: 'user', text: 'hi' }); + expect(entries).toHaveLength(1); + }); +}); + +describe('verifyDebugAccessKey', () => { + const originalSecret = process.env.DEBUG_ACCESS_KEY; + + afterEach(() => { + if (originalSecret === undefined) delete process.env.DEBUG_ACCESS_KEY; + else process.env.DEBUG_ACCESS_KEY = originalSecret; + }); + + it('rejects when DEBUG_ACCESS_KEY is not configured, regardless of key', () => { + delete process.env.DEBUG_ACCESS_KEY; + expect(verifyDebugAccessKey('anything')).toBe(false); + expect(verifyDebugAccessKey(undefined)).toBe(false); + }); + + it('rejects a missing key even when a secret is configured', () => { + process.env.DEBUG_ACCESS_KEY = 'correct-key'; + expect(verifyDebugAccessKey(undefined)).toBe(false); + }); + + it('rejects a mismatched key', () => { + process.env.DEBUG_ACCESS_KEY = 'correct-key'; + expect(verifyDebugAccessKey('wrong-key')).toBe(false); + }); + + it('accepts an exact match', () => { + process.env.DEBUG_ACCESS_KEY = 'correct-key'; + expect(verifyDebugAccessKey('correct-key')).toBe(true); + }); +}); + +describe('safeSerialize', () => { + it('passes through JSON-serializable data unchanged', () => { + expect(safeSerialize({ a: 1, b: 'two' })).toEqual({ a: 1, b: 'two' }); + }); + + it('passes through undefined unchanged', () => { + expect(safeSerialize(undefined)).toBeUndefined(); + }); + + it('reduces an Error instance to a plain, serializable shape', () => { + const result = safeSerialize(new Error('boom')); + expect(result).toEqual({ name: 'Error', message: 'boom' }); + expect(() => JSON.stringify(result)).not.toThrow(); + }); + + it('never throws on a circular object, stringifying it instead', () => { + const circular: Record = {}; + circular.self = circular; + const result = safeSerialize(circular); + expect(() => JSON.stringify(result)).not.toThrow(); + }); +}); diff --git a/src/lib/server/core/logger.ts b/src/lib/server/core/logger.ts new file mode 100644 index 0000000..25a7047 --- /dev/null +++ b/src/lib/server/core/logger.ts @@ -0,0 +1,103 @@ +import type { LogEntry, LogLevel, Logger } from '../../core/logger.js'; +import { timingSafeCompare } from './tokens.js'; + +const CONSOLE_METHOD: Record = { + debug: 'debug', + info: 'info', + warn: 'warn', + error: 'error' +}; + +export interface CreateLoggerOptions { + /** + * When `false`, entries in the `messages` category (full conversation + * content — see docs/LOGGING.md) skip the console mirror below. Every + * other category is unaffected, and `onEntry` (the hook `RealtimeSession` + * uses for browser forwarding, already gated by `debugSubscribed`) still + * always fires regardless — this only controls the *unconditional* + * stdout/container-log copy. Defaults to `true`, matching + * `DEBUG_LOG_MESSAGES`'s own default in config.ts. + */ + logMessages?: boolean; +} + +/** + * Builds a `Logger` that mirrors every call to `console.*` (visible in plain + * stdout/container logs with zero setup — the same "fail loud, visible by + * default" spirit as this app's existing boot-time `console.log` in + * server.js) and, if given, also invokes `onEntry` — the hook + * `RealtimeSession` uses to conditionally forward an entry to its browser as + * a `debug.log` event. `onEntry` runs synchronously and must never throw; + * callers that forward over a live WS connection are responsible for + * catching their own delivery errors (see `safeSerialize` below). + */ +export function createLogger( + onEntry?: (entry: LogEntry) => void, + options: CreateLoggerOptions = {} +): Logger { + const logMessages = options.logMessages ?? true; + + function log(level: LogLevel, category: string, message: string, data?: unknown): void { + const entry: LogEntry = { level, category, message, data, timestamp: Date.now() }; + if (logMessages || category !== 'messages') { + const method = CONSOLE_METHOD[level]; + if (data === undefined) { + console[method](`[${category}] ${message}`); + } else { + console[method](`[${category}] ${message}`, data); + } + } + onEntry?.(entry); + } + + return { + debug: (category, message, data) => log('debug', category, message, data), + info: (category, message, data) => log('info', category, message, data), + warn: (category, message, data) => log('warn', category, message, data), + error: (category, message, data) => log('error', category, message, data) + }; +} + +/** Ambient, console-only logger for callers with no per-session forwarding to wire up (e.g. analytics.ts, future project surfaces). */ +export const serverLogger: Logger = createLogger(); + +/** + * Checks a browser-supplied `debug.subscribe` key against `DEBUG_ACCESS_KEY`. + * Read directly from `process.env` at comparison time, deliberately never + * cached on `AppConfig` — same reasoning as `REALTIME_TOKEN_SECRET` in + * tokens.ts (per-test `process.env` mutation must keep working), but this + * secret is intentionally its own, separate from `REALTIME_TOKEN_SECRET`: a + * developer-access credential has a different blast radius than the + * "any visitor gets one automatically" session token. + * + * Unset `DEBUG_ACCESS_KEY` always returns `false` — an intentional, fully + * disabled state, not a misconfiguration to fail loud about (see + * docs/CONFIGURATION.md). Unlike `REALTIME_TOKEN_SECRET`, this is never + * presence-checked in `loadConfig()`. + */ +export function verifyDebugAccessKey(key: string | undefined): boolean { + const secret = process.env.DEBUG_ACCESS_KEY; + if (!secret || !key) return false; + return timingSafeCompare(key, secret); +} + +/** + * Defensive guard so a bad `data` argument passed to a `Logger` call (an + * `Error` instance, a value with a circular reference) can never throw inside + * `JSON.stringify` when a `debug.log` event is serialized for delivery — a + * misused log call must never be able to destabilize a live session's own + * traffic on the same WS connection. + */ +export function safeSerialize(data: unknown): unknown { + if (data === undefined) return undefined; + // `JSON.stringify` never throws on an Error — it just silently drops its + // (non-enumerable) name/message and serializes to `{}` — so this has to + // be checked explicitly, not inferred from a stringify failure. + if (data instanceof Error) return { name: data.name, message: data.message }; + try { + JSON.stringify(data); + return data; + } catch { + return String(data); + } +} diff --git a/src/lib/server/core/session.spec.ts b/src/lib/server/core/session.spec.ts index 0bbb16a..8e0057f 100644 --- a/src/lib/server/core/session.spec.ts +++ b/src/lib/server/core/session.spec.ts @@ -568,3 +568,253 @@ describe('RealtimeSession tool calls', () => { await vi.advanceTimersByTimeAsync(TEST_TOOL_TIMEOUT_MS); }); }); + +describe('RealtimeSession debug logging', () => { + const originalKey = process.env.DEBUG_ACCESS_KEY; + + afterEach(() => { + if (originalKey === undefined) delete process.env.DEBUG_ACCESS_KEY; + else process.env.DEBUG_ACCESS_KEY = originalKey; + }); + + it('forwards debug.log automatically in dev, with no subscribe needed', async () => { + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, DEFAULTS, recorder, TEST_TOOL_TIMEOUT_MS, true); + + socket.receive({ type: 'session.start' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ type: 'debug.log', category: 'session' }) + ) + ); + }); + + it('forwards nothing in prod until a valid debug.subscribe', async () => { + delete process.env.DEBUG_ACCESS_KEY; + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, DEFAULTS, recorder, TEST_TOOL_TIMEOUT_MS, false); + + socket.receive({ type: 'session.start' }); + await vi.waitFor(() => expect(provider.sessions).toHaveLength(1)); + expect(socket.sent.some((event) => event.type === 'debug.log')).toBe(false); + }); + + it('accepts debug.subscribe with a valid key in prod and begins forwarding', async () => { + process.env.DEBUG_ACCESS_KEY = 'correct-key'; + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, DEFAULTS, recorder, TEST_TOOL_TIMEOUT_MS, false); + + socket.receive({ type: 'debug.subscribe', key: 'correct-key' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual({ type: 'debug.subscribe.result', ok: true }) + ); + + socket.receive({ type: 'session.start' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ type: 'debug.log', category: 'session' }) + ) + ); + }); + + it('rejects debug.subscribe with an invalid key in prod and forwards nothing afterward', async () => { + process.env.DEBUG_ACCESS_KEY = 'correct-key'; + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, DEFAULTS, recorder, TEST_TOOL_TIMEOUT_MS, false); + + socket.receive({ type: 'debug.subscribe', key: 'wrong-key' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ type: 'debug.subscribe.result', ok: false }) + ) + ); + + socket.receive({ type: 'session.start' }); + await vi.waitFor(() => expect(provider.sessions).toHaveLength(1)); + expect(socket.sent.some((event) => event.type === 'debug.log')).toBe(false); + }); + + it('accepts debug.subscribe before session.start, unlike other client events', async () => { + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, DEFAULTS, recorder, TEST_TOOL_TIMEOUT_MS, true); + + socket.receive({ type: 'debug.subscribe' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual({ type: 'debug.subscribe.result', ok: true }) + ); + expect(socket.sent).not.toContainEqual( + expect.objectContaining({ type: 'error', code: 'invalid_client_event' }) + ); + }); + + it('never routes a debug.log entry through the analytics recorder', async () => { + const { session, socket, recorder } = await startDevSession(DEFAULTS); + + session.emitToOrchestrator({ + type: 'tool.call', + callId: 'call-1', + name: 'nonexistent_tool', + arguments: '{}' + }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual(expect.objectContaining({ type: 'debug.log' })) + ); + expect(recorder.eventLoggedCalls).toEqual([]); + }); + + it('never forwards one session’s debug logs to another session’s browser', async () => { + const toolRegistry = createToolRegistry([], {}); + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const a = makeSocket(); + const b = makeSocket(); + createRealtimeSession( + a.asWs, + provider, + { ...DEFAULTS, toolRegistry }, + recorder, + TEST_TOOL_TIMEOUT_MS, + true + ); + createRealtimeSession( + b.asWs, + provider, + { ...DEFAULTS, toolRegistry }, + recorder, + TEST_TOOL_TIMEOUT_MS, + true + ); + + a.socket.receive({ type: 'session.start' }); + await vi.waitFor(() => expect(provider.sessions).toHaveLength(1)); + provider.sessions[0].emitToOrchestrator({ + type: 'tool.call', + callId: 'only-in-a', + name: 'nonexistent_tool', + arguments: '{}' + }); + + await vi.waitFor(() => + expect(a.socket.sent).toContainEqual( + expect.objectContaining({ type: 'debug.log', category: 'tools' }) + ) + ); + expect( + b.socket.sent.some( + (event) => event.type === 'debug.log' && JSON.stringify(event).includes('only-in-a') + ) + ).toBe(false); + }); + + it('forwards the system instructions on session start', async () => { + const { socket } = await startDevSession(DEFAULTS); + expect(socket.sent).toContainEqual( + expect.objectContaining({ + type: 'debug.log', + category: 'messages', + data: { role: 'system', text: DEFAULTS.instructions } + }) + ); + }); + + it('forwards a typed user message', async () => { + const { socket } = await startDevSession(DEFAULTS); + socket.receive({ type: 'input_text.send', text: 'hello' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ + type: 'debug.log', + category: 'messages', + data: { role: 'user', text: 'hello' } + }) + ) + ); + }); + + it('forwards a voice user transcript', async () => { + const { session, socket } = await startDevSession(DEFAULTS); + session.emitToOrchestrator({ + type: 'transcript.delta', + role: 'user', + text: 'full transcript' + }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ + type: 'debug.log', + category: 'messages', + data: { role: 'user', text: 'full transcript' } + }) + ) + ); + }); + + it('forwards the assembled assistant message once done, never per delta', async () => { + const { session, socket } = await startDevSession(DEFAULTS); + + session.emitToOrchestrator({ type: 'transcript.delta', role: 'assistant', text: 'Hel' }); + session.emitToOrchestrator({ type: 'transcript.delta', role: 'assistant', text: 'lo' }); + expect( + socket.sent.some( + (event) => + event.type === 'debug.log' && + event.category === 'messages' && + event.message === 'Assistant message' + ) + ).toBe(false); + + session.emitToOrchestrator({ type: 'transcript.done', role: 'assistant' }); + await vi.waitFor(() => + expect(socket.sent).toContainEqual( + expect.objectContaining({ + type: 'debug.log', + category: 'messages', + data: { role: 'assistant', text: 'Hello' } + }) + ) + ); + }); + + it('does not mirror messages-category content to console when logMessages is false', async () => { + const spy = vi.spyOn(console, 'info').mockImplementation(() => {}); + await startDevSession(DEFAULTS, TEST_TOOL_TIMEOUT_MS, false); + expect(spy).not.toHaveBeenCalledWith(expect.stringContaining('[messages]'), expect.anything()); + spy.mockRestore(); + }); + + it('still forwards messages-category content to a subscribed browser when logMessages is false', async () => { + vi.spyOn(console, 'info').mockImplementation(() => {}); + const { socket } = await startDevSession(DEFAULTS, TEST_TOOL_TIMEOUT_MS, false); + expect(socket.sent).toContainEqual( + expect.objectContaining({ + type: 'debug.log', + category: 'messages', + data: { role: 'system', text: DEFAULTS.instructions } + }) + ); + }); +}); + +async function startDevSession( + defaults: typeof DEFAULTS, + timeoutMs = TEST_TOOL_TIMEOUT_MS, + logMessages = true +) { + const provider = new FakeProvider(); + const recorder = new FakeAnalyticsRecorder(); + const { socket, asWs } = makeSocket(); + createRealtimeSession(asWs, provider, defaults, recorder, timeoutMs, true, logMessages); + socket.receive({ type: 'session.start' }); + await vi.waitFor(() => expect(provider.sessions).toHaveLength(1)); + return { provider, session: provider.sessions[0], socket, recorder }; +} diff --git a/src/lib/server/core/session.ts b/src/lib/server/core/session.ts index 3db6ce5..b6a4c07 100644 --- a/src/lib/server/core/session.ts +++ b/src/lib/server/core/session.ts @@ -1,8 +1,10 @@ import { randomUUID } from 'node:crypto'; import WebSocket from 'ws'; +import type { LogEntry, Logger } from '../../core/logger.js'; import type { ClientEvent, ServerEvent, SessionStartConfig } from '../../core/protocol.js'; import { formatToolError } from '../../core/tools.js'; import type { AnalyticsRecorder } from './analytics.js'; +import { createLogger, safeSerialize, verifyDebugAccessKey } from './logger.js'; import type { ProviderSession, RealtimeProvider, ResolvedSessionConfig } from './provider.js'; import type { ToolRegistry } from './tools.js'; @@ -57,6 +59,10 @@ export class RealtimeSession { >(); /** Assistant voice replies stream as many transcript.delta chunks then one text-less transcript.done — see docs/ANALYTICS.md. */ private assistantTranscriptBuffer = ''; + /** True once this connection is allowed to receive `debug.log` events — see docs/LOGGING.md. Starts true in dev (frictionless), false in prod until a valid `debug.subscribe`. */ + private debugSubscribed = false; + /** Forwards to this session's own browser only when `debugSubscribed` — see forwardDebugLog. Also mirrors to console, except the `messages` category when `DEBUG_LOG_MESSAGES=false` — see createLogger. */ + private readonly logger: Logger; constructor( private readonly browserSocket: WebSocket, @@ -64,8 +70,14 @@ export class RealtimeSession { private readonly defaults: SessionDefaults, private readonly recorder: AnalyticsRecorder, /** How long a client-executed tool call may go unanswered before we give up on it. */ - private readonly clientToolTimeoutMs: number + private readonly clientToolTimeoutMs: number, + /** Dev builds forward debug logs automatically; prod requires `debug.subscribe` with a valid key. See docs/LOGGING.md. */ + private readonly isDev: boolean = false, + /** Gates the `messages` category's console mirror only — browser forwarding is unaffected. See `DEBUG_LOG_MESSAGES` in config.ts and docs/LOGGING.md. */ + logMessages: boolean = true ) { + this.debugSubscribed = isDev; + this.logger = createLogger((entry) => this.forwardDebugLog(entry), { logMessages }); this.browserSocket.on('message', (data, isBinary) => { void this.handleBrowserMessage(data, isBinary); }); @@ -79,6 +91,7 @@ export class RealtimeSession { private async handleBrowserMessage(data: WebSocket.RawData, isBinary: boolean): Promise { if (isBinary) { + this.logger.warn('ws', 'Rejected binary frame from browser.'); this.sendToBrowser({ type: 'error', code: 'invalid_client_event', @@ -91,6 +104,7 @@ export class RealtimeSession { try { event = JSON.parse(data.toString()); } catch { + this.logger.warn('ws', 'Rejected malformed JSON from browser.'); this.sendToBrowser({ type: 'error', code: 'invalid_client_event', @@ -107,7 +121,12 @@ export class RealtimeSession { this.close('client_requested'); return; } + if (event.type === 'debug.subscribe') { + this.handleDebugSubscribe(event.key); + return; + } if (this.state !== 'active' || !this.providerSession) { + this.logger.warn('ws', `Rejected '${event.type}' before session.start.`); this.sendToBrowser({ type: 'error', code: 'invalid_client_event', @@ -126,6 +145,7 @@ export class RealtimeSession { if (event.type === 'input_text.send') { // Typed text is always already a complete string — unlike the voice // path, no buffering is needed. + this.logger.info('messages', 'User message', { role: 'user', text: event.text }); this.recorder.messageLogged({ sessionId: this.sessionId!, role: 'user', @@ -153,10 +173,12 @@ export class RealtimeSession { providerSession = await this.provider.createSession(config); } catch (err) { this.state = 'closed'; + const message = err instanceof Error ? err.message : 'Failed to start session.'; + this.logger.error('session', 'Failed to start session.', { message }); this.sendToBrowser({ type: 'error', code: 'upstream_unavailable', - message: err instanceof Error ? err.message : 'Failed to start session.' + message }); this.browserSocket.close(); return; @@ -174,6 +196,18 @@ export class RealtimeSession { const sessionId = randomUUID(); this.sessionId = sessionId; this.state = 'active'; + this.logger.info('session', 'Session started.', { + sessionId, + model: config.model, + voice: config.voice + }); + // Logged once here, alongside the user/assistant message logging below, + // so the debug panel can show the full conversation context — the + // system prompt is otherwise invisible while debugging a live session. + this.logger.info('messages', 'System instructions', { + role: 'system', + text: config.instructions + }); this.recorder.sessionStarted({ sessionId, model: config.model, @@ -201,6 +235,7 @@ export class RealtimeSession { // transcript.done{role:'user'} ever emitted today — log // immediately rather than buffering. Rests on unverified live // behavior; see docs/ANALYTICS.md. + this.logger.info('messages', 'User message', { role: 'user', text: event.text }); this.recorder.messageLogged({ sessionId: this.sessionId!, role: 'user', @@ -214,6 +249,7 @@ export class RealtimeSession { if (event.type === 'transcript.done' && event.role === 'assistant') { const text = this.assistantTranscriptBuffer; this.assistantTranscriptBuffer = ''; + this.logger.info('messages', 'Assistant message', { role: 'assistant', text }); this.recorder.messageLogged({ sessionId: this.sessionId!, role: 'assistant', @@ -247,8 +283,10 @@ export class RealtimeSession { arguments: event.arguments, startedAt: Date.now() }); + this.logger.debug('tools', `Tool call started: ${event.name}`, { callId: event.callId }); const definition = this.defaults.toolRegistry.definitions.find((d) => d.name === event.name); if (!definition) { + this.logger.warn('tools', `Unknown tool "${event.name}".`, { callId: event.callId }); this.resolveToolCall(event.callId, formatToolError(`Unknown tool "${event.name}".`)); return; } @@ -257,6 +295,7 @@ export class RealtimeSession { this.sendToBrowser(event); const timeout = setTimeout(() => { this.pendingClientToolCalls.delete(event.callId); + this.logger.warn('tools', `Tool call timed out: ${event.name}`, { callId: event.callId }); this.resolveToolCall(event.callId, formatToolError('Client tool call timed out.')); }, this.clientToolTimeoutMs); this.pendingClientToolCalls.set(event.callId, timeout); @@ -297,6 +336,10 @@ export class RealtimeSession { // guarded defensively rather than asserted, so a future refactor // that breaks the invariant fails soft here instead of crashing. this.toolCallMeta.delete(callId); + this.logger.debug('tools', `Tool call completed: ${meta.name}`, { + callId, + durationMs: Date.now() - meta.startedAt + }); this.recorder.toolCallLogged({ sessionId: this.sessionId!, callId, @@ -316,6 +359,7 @@ export class RealtimeSession { private close(reason: string): void { if (this.state === 'closing' || this.state === 'closed') return; this.state = 'closing'; + this.logger.info('session', `Session closed: ${reason}`); for (const timeout of this.pendingClientToolCalls.values()) clearTimeout(timeout); this.pendingClientToolCalls.clear(); this.providerSession?.close(reason); @@ -348,6 +392,35 @@ export class RealtimeSession { this.browserSocket.send(JSON.stringify(event)); } + /** + * Verifies a `debug.subscribe` request and replies with the result. In + * dev, any request succeeds (frictionless — see docs/LOGGING.md); in + * prod, `key` must match `DEBUG_ACCESS_KEY`. + */ + private handleDebugSubscribe(key: string | undefined): void { + this.debugSubscribed = this.isDev || verifyDebugAccessKey(key); + this.sendToBrowser({ + type: 'debug.subscribe.result', + ok: this.debugSubscribed, + reason: this.debugSubscribed ? undefined : 'Invalid or missing debug access key.' + }); + } + + /** + * Forwards a log entry to this session's own browser only — never another + * session's, since each `RealtimeSession` instance owns exactly one + * `browserSocket`. No-ops until `debugSubscribed`. Never lets a bad log + * entry (e.g. unserializable `data`) affect the session itself. + */ + private forwardDebugLog(entry: LogEntry): void { + if (!this.debugSubscribed) return; + try { + this.sendToBrowser({ type: 'debug.log', ...entry, data: safeSerialize(entry.data) }); + } catch { + // Forwarding a debug entry must never break real session traffic. + } + } + // Guarded the same way sendToBrowser is: tool resolution can now reach // the provider from an async callback (executor await, timeout) rather // than only from a browser message already known to be in the 'active' @@ -362,7 +435,17 @@ export function createRealtimeSession( provider: RealtimeProvider, defaults: SessionDefaults, recorder: AnalyticsRecorder, - clientToolTimeoutMs: number + clientToolTimeoutMs: number, + isDev = false, + logMessages = true ): RealtimeSession { - return new RealtimeSession(browserSocket, provider, defaults, recorder, clientToolTimeoutMs); + return new RealtimeSession( + browserSocket, + provider, + defaults, + recorder, + clientToolTimeoutMs, + isDev, + logMessages + ); } diff --git a/src/lib/server/core/tokens.ts b/src/lib/server/core/tokens.ts index 61a3b24..744496f 100644 --- a/src/lib/server/core/tokens.ts +++ b/src/lib/server/core/tokens.ts @@ -58,7 +58,13 @@ function sign(payload: string): string { return createHmac('sha256', getSecret()).update(payload).digest('hex'); } -function timingSafeCompare(a: string, b: string): boolean { +/** + * Generic timing-safe string comparison — exported for reuse by other + * secret-comparison flows (e.g. `$lib/server/core/logger.ts`'s + * `verifyDebugAccessKey`) that deliberately keep their own secret separate + * from `REALTIME_TOKEN_SECRET` rather than importing anything else from here. + */ +export function timingSafeCompare(a: string, b: string): boolean { const bufA = Buffer.from(a); const bufB = Buffer.from(b); if (bufA.length !== bufB.length) return false; diff --git a/src/lib/server/core/ws-handler.ts b/src/lib/server/core/ws-handler.ts index 1f5c80c..b752230 100644 --- a/src/lib/server/core/ws-handler.ts +++ b/src/lib/server/core/ws-handler.ts @@ -12,6 +12,10 @@ export interface RealtimeUpgradeDeps { defaults: SessionDefaults; recorder: AnalyticsRecorder; clientToolTimeoutMs: number; + /** Gates debug-log forwarding — see RealtimeSession and docs/LOGGING.md. */ + isDev: boolean; + /** Gates the `messages` category's console mirror — see `DEBUG_LOG_MESSAGES` in config.ts and docs/LOGGING.md. */ + logMessages: boolean; } // `noServer: true` + `handleUpgrade` below is what lets this share an @@ -50,7 +54,9 @@ export function handleRealtimeUpgrade( deps.provider, deps.defaults, deps.recorder, - deps.clientToolTimeoutMs + deps.clientToolTimeoutMs, + deps.isDev, + deps.logMessages ); }); } diff --git a/src/routes/demo/realtime/+page.svelte b/src/routes/demo/realtime/+page.svelte index 345416e..3b588aa 100644 --- a/src/routes/demo/realtime/+page.svelte +++ b/src/routes/demo/realtime/+page.svelte @@ -1,9 +1,13 @@ @@ -129,6 +141,8 @@ + +