Browse Source
Server- and client-side infrastructure other subsystems (humanoid, analytics, project surfaces) can log into: an open-category Logger contract, per-session WS forwarding gated by DEBUG_ACCESS_KEY in prod (frictionless in dev), and a production-shippable DebugPanel.svelte. Also logs full conversation content (system prompt, user/assistant messages) under its own `messages` category so a session's history is trackable while debugging, with DEBUG_LOG_MESSAGES to keep that content out of the unconditional console/stdout mirror when desired. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>main
24 changed files with 1606 additions and 15 deletions
@ -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 `<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. |
||||
@ -0,0 +1,300 @@ |
|||||
|
<script lang="ts"> |
||||
|
import type { LogLevel } from '../../core/logger.js'; |
||||
|
import { clearLogs, debugLogStore, type DisplayLogEntry } from './logger.js'; |
||||
|
import type { ServerLogForwarder, ServerLogForwarderState } from './server-log-forwarder.js'; |
||||
|
|
||||
|
/** |
||||
|
* Production-shippable debug panel — lives in `$lib/client/core` (not |
||||
|
* `/demo`, which is dev-only-gated scaffolding) since the key-based auth |
||||
|
* on `forwarder`, not route removal, is what protects it in prod. See |
||||
|
* docs/LOGGING.md. |
||||
|
* |
||||
|
* `forwarder` is optional: with none given (or on a page with no realtime |
||||
|
* connection at all), the panel still shows the ambient client-side log |
||||
|
* buffer via `debugLogStore` — that part never needs a connection. |
||||
|
*/ |
||||
|
interface Props { |
||||
|
forwarder?: ServerLogForwarder | null; |
||||
|
} |
||||
|
|
||||
|
let { forwarder = null }: Props = $props(); |
||||
|
|
||||
|
const LEVELS: LogLevel[] = ['debug', 'info', 'warn', 'error']; |
||||
|
|
||||
|
let open = $state(false); |
||||
|
let logEntries = $state<DisplayLogEntry[]>([]); |
||||
|
let forwarderState = $state<ServerLogForwarderState | null>(null); |
||||
|
let categoryFilter = $state(''); |
||||
|
let levelFilter = $state<Record<LogLevel, boolean>>({ |
||||
|
debug: true, |
||||
|
info: true, |
||||
|
warn: true, |
||||
|
error: true |
||||
|
}); |
||||
|
let keyInput = $state(''); |
||||
|
let expandedKey = $state<string | null>(null); |
||||
|
|
||||
|
// `forwarder` is a prop that can transition from null to a real object |
||||
|
// once a page's realtime client connects, so this must be an $effect (re- |
||||
|
// runs on that change), not onMount (runs once). |
||||
|
$effect(() => { |
||||
|
return debugLogStore.subscribe((next) => { |
||||
|
logEntries = next; |
||||
|
}); |
||||
|
}); |
||||
|
|
||||
|
$effect(() => { |
||||
|
if (!forwarder) { |
||||
|
forwarderState = null; |
||||
|
return; |
||||
|
} |
||||
|
return forwarder.subscribe((next) => { |
||||
|
forwarderState = next; |
||||
|
}); |
||||
|
}); |
||||
|
|
||||
|
const filtered = $derived( |
||||
|
logEntries.filter((entry) => { |
||||
|
if (!levelFilter[entry.level]) return false; |
||||
|
const needle = categoryFilter.trim().toLowerCase(); |
||||
|
return needle === '' || entry.category.toLowerCase().includes(needle); |
||||
|
}) |
||||
|
); |
||||
|
|
||||
|
const statusLabel = $derived.by(() => { |
||||
|
if (!forwarder) return 'local only'; |
||||
|
if (forwarder.isDev) return 'server logs: live (dev)'; |
||||
|
return forwarderState?.subscribed ? 'server logs: subscribed' : 'server logs: not subscribed'; |
||||
|
}); |
||||
|
|
||||
|
function entryKey(entry: DisplayLogEntry): string { |
||||
|
return `${entry.timestamp}:${entry.category}:${entry.message}`; |
||||
|
} |
||||
|
|
||||
|
function toggleLevel(level: LogLevel): void { |
||||
|
levelFilter = { ...levelFilter, [level]: !levelFilter[level] }; |
||||
|
} |
||||
|
|
||||
|
function toggleExpanded(entry: DisplayLogEntry): void { |
||||
|
const key = entryKey(entry); |
||||
|
expandedKey = expandedKey === key ? null : key; |
||||
|
} |
||||
|
|
||||
|
function submitKey(e: Event): void { |
||||
|
e.preventDefault(); |
||||
|
const key = keyInput.trim(); |
||||
|
if (!key || !forwarder) return; |
||||
|
forwarder.subscribeWithKey(key); |
||||
|
} |
||||
|
|
||||
|
function formatTime(ts: number): string { |
||||
|
return new Date(ts).toLocaleTimeString(); |
||||
|
} |
||||
|
</script> |
||||
|
|
||||
|
<button type="button" class="toggle" onclick={() => (open = !open)}> |
||||
|
{open ? 'Close debug log' : `Debug log (${logEntries.length})`} |
||||
|
</button> |
||||
|
|
||||
|
{#if open} |
||||
|
<div class="panel"> |
||||
|
<div class="header"> |
||||
|
<strong>Debug log</strong> |
||||
|
<span class="status">{statusLabel}</span> |
||||
|
<button type="button" onclick={clearLogs}>Clear</button> |
||||
|
</div> |
||||
|
|
||||
|
{#if forwarder && !forwarder.isDev && !forwarderState?.subscribed} |
||||
|
<form class="key-form" onsubmit={submitKey}> |
||||
|
<input type="password" placeholder="Debug access key" bind:value={keyInput} /> |
||||
|
<button type="submit">Subscribe</button> |
||||
|
{#if forwarderState?.lastError} |
||||
|
<span class="error">{forwarderState.lastError}</span> |
||||
|
{/if} |
||||
|
</form> |
||||
|
{/if} |
||||
|
|
||||
|
<div class="filters"> |
||||
|
<input type="text" placeholder="Filter by category…" bind:value={categoryFilter} /> |
||||
|
{#each LEVELS as level (level)} |
||||
|
<label class="checkbox"> |
||||
|
<input type="checkbox" checked={levelFilter[level]} onchange={() => toggleLevel(level)} /> |
||||
|
{level} |
||||
|
</label> |
||||
|
{/each} |
||||
|
</div> |
||||
|
|
||||
|
<ul class="entries"> |
||||
|
{#each filtered as entry (entryKey(entry))} |
||||
|
<li class={`entry ${entry.level}`}> |
||||
|
<button type="button" class="entry-row" onclick={() => toggleExpanded(entry)}> |
||||
|
<span class="time">{formatTime(entry.timestamp)}</span> |
||||
|
<span class="source">{entry.source}</span> |
||||
|
<span class="level">{entry.level}</span> |
||||
|
<span class="category">{entry.category}</span> |
||||
|
<span class="message">{entry.message}</span> |
||||
|
</button> |
||||
|
{#if expandedKey === entryKey(entry) && entry.data !== undefined} |
||||
|
<pre class="data">{JSON.stringify(entry.data, null, 2)}</pre> |
||||
|
{/if} |
||||
|
</li> |
||||
|
{:else} |
||||
|
<li class="empty">No log entries.</li> |
||||
|
{/each} |
||||
|
</ul> |
||||
|
</div> |
||||
|
{/if} |
||||
|
|
||||
|
<style> |
||||
|
.toggle { |
||||
|
position: fixed; |
||||
|
bottom: 1rem; |
||||
|
right: 1rem; |
||||
|
z-index: 9999; |
||||
|
font-family: sans-serif; |
||||
|
font-size: 0.8rem; |
||||
|
padding: 0.4rem 0.7rem; |
||||
|
border-radius: 0.3rem; |
||||
|
border: 1px solid #ccc; |
||||
|
background: #fff; |
||||
|
box-shadow: 0 1px 4px rgba(0, 0, 0, 0.2); |
||||
|
cursor: pointer; |
||||
|
} |
||||
|
|
||||
|
.panel { |
||||
|
position: fixed; |
||||
|
bottom: 3.5rem; |
||||
|
right: 1rem; |
||||
|
z-index: 9999; |
||||
|
width: 28rem; |
||||
|
max-width: calc(100vw - 2rem); |
||||
|
max-height: 60vh; |
||||
|
display: flex; |
||||
|
flex-direction: column; |
||||
|
gap: 0.5rem; |
||||
|
padding: 0.6rem; |
||||
|
border-radius: 0.4rem; |
||||
|
border: 1px solid #ccc; |
||||
|
background: #fff; |
||||
|
box-shadow: 0 2px 10px rgba(0, 0, 0, 0.25); |
||||
|
font-family: sans-serif; |
||||
|
font-size: 0.78rem; |
||||
|
color: #222; |
||||
|
} |
||||
|
|
||||
|
.header { |
||||
|
display: flex; |
||||
|
align-items: center; |
||||
|
gap: 0.5rem; |
||||
|
} |
||||
|
|
||||
|
.status { |
||||
|
flex: 1; |
||||
|
color: #666; |
||||
|
} |
||||
|
|
||||
|
.key-form { |
||||
|
display: flex; |
||||
|
align-items: center; |
||||
|
gap: 0.4rem; |
||||
|
} |
||||
|
|
||||
|
.key-form input[type='password'] { |
||||
|
flex: 1; |
||||
|
} |
||||
|
|
||||
|
.key-form .error { |
||||
|
color: #b00020; |
||||
|
} |
||||
|
|
||||
|
.filters { |
||||
|
display: flex; |
||||
|
flex-wrap: wrap; |
||||
|
align-items: center; |
||||
|
gap: 0.6rem; |
||||
|
} |
||||
|
|
||||
|
.filters input[type='text'] { |
||||
|
flex: 1; |
||||
|
min-width: 8rem; |
||||
|
} |
||||
|
|
||||
|
.checkbox { |
||||
|
display: flex; |
||||
|
align-items: center; |
||||
|
gap: 0.2rem; |
||||
|
white-space: nowrap; |
||||
|
} |
||||
|
|
||||
|
.entries { |
||||
|
list-style: none; |
||||
|
margin: 0; |
||||
|
padding: 0; |
||||
|
overflow-y: auto; |
||||
|
border-top: 1px solid #eee; |
||||
|
} |
||||
|
|
||||
|
.entry { |
||||
|
border-bottom: 1px solid #eee; |
||||
|
} |
||||
|
|
||||
|
.entry-row { |
||||
|
display: flex; |
||||
|
width: 100%; |
||||
|
gap: 0.4rem; |
||||
|
padding: 0.25rem 0; |
||||
|
background: none; |
||||
|
border: none; |
||||
|
text-align: left; |
||||
|
font: inherit; |
||||
|
cursor: pointer; |
||||
|
} |
||||
|
|
||||
|
.time, |
||||
|
.source { |
||||
|
color: #999; |
||||
|
flex-shrink: 0; |
||||
|
} |
||||
|
|
||||
|
.level { |
||||
|
flex-shrink: 0; |
||||
|
font-weight: 600; |
||||
|
width: 3.2rem; |
||||
|
} |
||||
|
|
||||
|
.entry.debug .level { |
||||
|
color: #888; |
||||
|
} |
||||
|
.entry.info .level { |
||||
|
color: #1a73e8; |
||||
|
} |
||||
|
.entry.warn .level { |
||||
|
color: #b06000; |
||||
|
} |
||||
|
.entry.error .level { |
||||
|
color: #b00020; |
||||
|
} |
||||
|
|
||||
|
.category { |
||||
|
flex-shrink: 0; |
||||
|
color: #555; |
||||
|
} |
||||
|
|
||||
|
.message { |
||||
|
overflow-wrap: anywhere; |
||||
|
} |
||||
|
|
||||
|
.data { |
||||
|
margin: 0 0 0.4rem 0; |
||||
|
padding: 0.4rem; |
||||
|
background: #f5f5f5; |
||||
|
border-radius: 0.25rem; |
||||
|
overflow-x: auto; |
||||
|
font-size: 0.72rem; |
||||
|
} |
||||
|
|
||||
|
.empty { |
||||
|
padding: 0.5rem 0; |
||||
|
color: #999; |
||||
|
} |
||||
|
</style> |
||||
@ -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'); |
||||
|
}); |
||||
|
}); |
||||
@ -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([]); |
||||
|
}); |
||||
|
}); |
||||
@ -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(); |
||||
|
} |
||||
@ -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 }); |
||||
|
}); |
||||
|
}); |
||||
@ -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(); |
||||
|
} |
||||
|
}; |
||||
|
} |
||||
@ -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() {} |
||||
|
}; |
||||
@ -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<string, unknown> = {}; |
||||
|
circular.self = circular; |
||||
|
const result = safeSerialize(circular); |
||||
|
expect(() => JSON.stringify(result)).not.toThrow(); |
||||
|
}); |
||||
|
}); |
||||
@ -0,0 +1,103 @@ |
|||||
|
import type { LogEntry, LogLevel, Logger } from '../../core/logger.js'; |
||||
|
import { timingSafeCompare } from './tokens.js'; |
||||
|
|
||||
|
const CONSOLE_METHOD: Record<LogLevel, 'debug' | 'info' | 'warn' | 'error'> = { |
||||
|
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); |
||||
|
} |
||||
|
} |
||||
Loading…
Reference in new issue