Browse Source
Records session start/end, conversation messages, tool calls, and errors via better-sqlite3, hooked into RealtimeSession's existing choke points so no client-side changes are needed. Also fixes a pre-existing gap where an upstream-initiated disconnect only forwarded session.closed to the browser without ever calling close(), so no session end time was ever recorded for that path. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>main
12 changed files with 701 additions and 19 deletions
@ -0,0 +1,66 @@ |
|||
# Analytics |
|||
|
|||
Server-side recording of session volume, conversation content, tool usage, and failures for the realtime session relay. Backed by a small local SQLite database — no client-side instrumentation, since every session event already passes through our server (see [REALTIME_SESSION.md](REALTIME_SESSION.md)'s connection flow). This fills a seam that doc explicitly anticipated: _"we can add moderation, analytics, avatar-specific processing... in the middle later — without ever touching the browser client."_ |
|||
|
|||
## The hook point |
|||
|
|||
`RealtimeSession` (`session.ts`) is the one place every session event in both directions already funnels through. Analytics attaches at choke points that already exist there for other reasons — `start()`, `close()`, `resolveToolCall()`, `sendToBrowser()` — rather than adding new plumbing. See `src/lib/server/core/analytics.ts` for the `AnalyticsRecorder` interface and its `better-sqlite3`-backed implementation. |
|||
|
|||
## Why `better-sqlite3`, not `node:sqlite` |
|||
|
|||
Node has an experimental built-in SQLite module, but `better-sqlite3` was chosen instead: it's the mature, widely-used library with a stable synchronous API, which is what keeps every `AnalyticsRecorder` call in `session.ts` a plain fire-and-forget call rather than something that needs `await`/error-handling threaded through the session's existing synchronous methods. |
|||
|
|||
## The transcript-buffering gotcha |
|||
|
|||
`transcript.done` (see `protocol.ts`) carries only `{ role }` — no text. Full message text has to be assembled server-side: |
|||
|
|||
- **Typed user text** (`input_text.send`): already a complete string — logged directly, no buffering. |
|||
- **Assistant voice replies**: stream as many `transcript.delta{role:'assistant'}` chunks as OpenAI cares to send, followed by one text-less `transcript.done{role:'assistant'}`. `RealtimeSession` accumulates deltas into `assistantTranscriptBuffer` and flushes+logs the concatenated text on `done`. |
|||
- **User voice transcripts**: today, OpenAI's `conversation.item.input_audio_transcription.completed` maps (in `providers/openai.ts`) to a single `transcript.delta{role:'user'}` event that already carries the _entire_ transcript — no corresponding `transcript.done{role:'user'}` is ever emitted by that mapping. So a user-role delta is logged immediately as a complete message, not buffered. |
|||
|
|||
**This rests on unverified live behavior** — the same caveat class as REALTIME_SESSION.md's "Still unverified" note on this exact OpenAI event. If a live session ever produces more than one `messages` row for a single spoken user turn, that assumption has broken and this logic needs revisiting (see "Verifying changes" below for how to check). |
|||
|
|||
## A bundled correctness fix: upstream-disconnect now actually closes the session |
|||
|
|||
Before this change, `handleProviderEvent` only _forwarded_ a provider-originated `session.closed` event (e.g. the upstream WebSocket dropping) to the browser — it never called `this.close()`. That meant `RealtimeSession`'s own state never updated and no session end time was ever recorded for that path. Since "session end time" is a stated goal of this feature, `handleProviderEvent` now also calls `this.close('upstream_disconnected')` when it sees a `session.closed` event (forwarding first, since `close()` moves the browser socket out of `OPEN` and `sendToBrowser` no-ops after that). |
|||
|
|||
## Schema |
|||
|
|||
Four tables, `CREATE TABLE IF NOT EXISTS` on startup — no migration framework; a future column addition is a manual `ALTER TABLE` added to `SCHEMA_SQL` in `analytics.ts`: |
|||
|
|||
- `sessions(id, model, voice, started_at, ended_at, end_reason)` |
|||
- `messages(id, session_id, role, text, created_at)` |
|||
- `tool_calls(id, session_id, call_id, name, arguments, output, duration_ms, created_at)` |
|||
- `events(id, session_id, type, detail, created_at)` — `session_id` is nullable here (only here): a validation error can occur before `session.start` completes, when no `sessions` row exists yet. |
|||
|
|||
Foreign keys are declared for documentation but explicitly not enforced (`PRAGMA foreign_keys = OFF` in the constructor — `better-sqlite3` defaults this pragma to _on_, so it has to be turned off explicitly, not just left unset) — this is a logging sink, not a system of record, and a stray write should never be silently dropped by a constraint violation. |
|||
|
|||
## Configuration |
|||
|
|||
`ANALYTICS_DB_PATH` (optional) — defaults to `./data/analytics.db`. The parent directory is created automatically if missing. `/data` is gitignored. |
|||
|
|||
## PII and retention |
|||
|
|||
`analytics.db` stores full raw conversation text (both roles) and tool call arguments/outputs verbatim, in a local, unencrypted SQLite file, with no retention window, no rotation, no redaction, and no per-user consent tracking. That's fine for internal development or a demo of this base template — it is **not** production-safe as shipped. A client project deploying this for real users needs to add a real retention/redaction policy before treating this as production telemetry; don't assume GDPR/CCPA compliance out of the box. |
|||
|
|||
## What's deliberately not built yet |
|||
|
|||
- A query/reporting UI — this is a write-only sink today, read it with the `sqlite3` CLI or any SQLite client. |
|||
- Migration tooling beyond manual `ALTER TABLE` additions to `SCHEMA_SQL`. |
|||
- DB export/backup, log rotation for the file itself. |
|||
- A graceful-shutdown/flush hook — no composition root in this codebase has one for anything yet, including the existing provider connections. |
|||
- Multi-process-safe writes beyond WAL's built-in single-writer guarantee (matches the existing "in-memory, single-process only" constraint on session storage itself). |
|||
|
|||
## Verifying changes |
|||
|
|||
- `npm run check` / `npm run lint` — type/lint correctness. Note `check` uses `bundler` module resolution and will **not** catch a missing `.js` extension on a relative import inside `src/lib/server/core/**`. |
|||
- `npm run build` — also runs the standalone `tsc -p tsconfig.server.json` compile (`nodenext` resolution) that `server.js` depends on; this is the step that catches a missing `.js` extension or a file placed outside that config's `include` globs. |
|||
- `npm run test:unit` — `analytics.spec.ts` (schema + each recorder method against `:memory:`, plus a WAL-mode check against a real temp file) and the extended `session.spec.ts` (asserts `AnalyticsRecorder` calls happen at the right lifecycle points, using a hand-written `FakeAnalyticsRecorder` in the same no-`vi.fn()` style as this file's other fakes). |
|||
- **Live smoke test**: set `.env`, `npm run dev`, open `/demo/realtime`, and hold a real conversation — a typed message, a full voice turn in both directions, and a tool call (the demo project registers `get_current_time` (server) and `flash_page` (client) out of the box). Then inspect `data/analytics.db` directly: |
|||
```bash |
|||
sqlite3 data/analytics.db "select * from sessions;" |
|||
sqlite3 data/analytics.db "select id, role, substr(text,1,80), created_at from messages order by id;" |
|||
sqlite3 data/analytics.db "select call_id, name, duration_ms from tool_calls;" |
|||
sqlite3 data/analytics.db "select type, detail from events;" |
|||
``` |
|||
Confirm exactly one assistant `messages` row per spoken AI turn with the **full** assembled text (not fragments), exactly one user `messages` row per spoken user turn (the direct check on the unverified single-chunk assumption above), and — kill the dev server or close the tab mid-session once — that `sessions.ended_at`/`end_reason` get populated (the direct check on the bug fix above). Remember `src/lib/server/core/**` isn't part of Vite's HMR — restart `npm run dev` after editing anything here. |
|||
@ -0,0 +1,151 @@ |
|||
import { mkdtempSync, rmSync } from 'node:fs'; |
|||
import { tmpdir } from 'node:os'; |
|||
import { join } from 'node:path'; |
|||
import { afterEach, describe, expect, it } from 'vitest'; |
|||
import { SqliteAnalyticsRecorder } from './analytics.js'; |
|||
|
|||
describe('SqliteAnalyticsRecorder', () => { |
|||
it('creates all four tables on construction', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
const tables = recorder.rawDb |
|||
.prepare("SELECT name FROM sqlite_master WHERE type = 'table'") |
|||
.all() |
|||
.map((row) => (row as { name: string }).name); |
|||
expect(tables).toEqual( |
|||
expect.arrayContaining(['sessions', 'messages', 'tool_calls', 'events']) |
|||
); |
|||
}); |
|||
|
|||
it('persists a started session and leaves ended_at/end_reason null', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.sessionStarted({ |
|||
sessionId: 'session-1', |
|||
model: 'test-model', |
|||
voice: 'coral', |
|||
startedAt: 1000 |
|||
}); |
|||
|
|||
const row = recorder.rawDb.prepare('SELECT * FROM sessions WHERE id = ?').get('session-1'); |
|||
expect(row).toMatchObject({ |
|||
id: 'session-1', |
|||
model: 'test-model', |
|||
voice: 'coral', |
|||
started_at: 1000, |
|||
ended_at: null, |
|||
end_reason: null |
|||
}); |
|||
}); |
|||
|
|||
it('updates the same session row on sessionEnded, leaving other columns unchanged', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.sessionStarted({ |
|||
sessionId: 'session-1', |
|||
model: 'test-model', |
|||
voice: undefined, |
|||
startedAt: 1000 |
|||
}); |
|||
recorder.sessionEnded({ sessionId: 'session-1', endedAt: 2000, reason: 'client_requested' }); |
|||
|
|||
const row = recorder.rawDb.prepare('SELECT * FROM sessions WHERE id = ?').get('session-1'); |
|||
expect(row).toMatchObject({ |
|||
id: 'session-1', |
|||
model: 'test-model', |
|||
started_at: 1000, |
|||
ended_at: 2000, |
|||
end_reason: 'client_requested' |
|||
}); |
|||
}); |
|||
|
|||
it('logs messages for both roles', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.messageLogged({ sessionId: 'session-1', role: 'user', text: 'hi', loggedAt: 1 }); |
|||
recorder.messageLogged({ |
|||
sessionId: 'session-1', |
|||
role: 'assistant', |
|||
text: 'hello there', |
|||
loggedAt: 2 |
|||
}); |
|||
|
|||
const rows = recorder.rawDb |
|||
.prepare('SELECT session_id, role, text, created_at FROM messages ORDER BY id') |
|||
.all(); |
|||
expect(rows).toEqual([ |
|||
{ session_id: 'session-1', role: 'user', text: 'hi', created_at: 1 }, |
|||
{ session_id: 'session-1', role: 'assistant', text: 'hello there', created_at: 2 } |
|||
]); |
|||
}); |
|||
|
|||
it('round-trips a logged tool call', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.toolCallLogged({ |
|||
sessionId: 'session-1', |
|||
callId: 'call-1', |
|||
name: 'get_current_time', |
|||
arguments: '{}', |
|||
output: JSON.stringify({ time: '12:00' }), |
|||
durationMs: 42, |
|||
loggedAt: 3 |
|||
}); |
|||
|
|||
const row = recorder.rawDb.prepare('SELECT * FROM tool_calls WHERE call_id = ?').get('call-1'); |
|||
expect(row).toMatchObject({ |
|||
session_id: 'session-1', |
|||
call_id: 'call-1', |
|||
name: 'get_current_time', |
|||
arguments: '{}', |
|||
output: JSON.stringify({ time: '12:00' }), |
|||
duration_ms: 42 |
|||
}); |
|||
}); |
|||
|
|||
it('logs an event with a null session_id for a pre-session error', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.eventLogged({ |
|||
sessionId: null, |
|||
type: 'error', |
|||
detail: JSON.stringify({ type: 'error', code: 'invalid_client_event' }), |
|||
loggedAt: 4 |
|||
}); |
|||
|
|||
const row = recorder.rawDb.prepare('SELECT * FROM events WHERE type = ?').get('error') as { |
|||
session_id: string | null; |
|||
detail: string; |
|||
}; |
|||
expect(row.session_id).toBeNull(); |
|||
expect(JSON.parse(row.detail)).toEqual({ type: 'error', code: 'invalid_client_event' }); |
|||
}); |
|||
|
|||
it('logs an event against a real session_id once a session exists', () => { |
|||
const recorder = new SqliteAnalyticsRecorder(':memory:'); |
|||
recorder.eventLogged({ |
|||
sessionId: 'session-1', |
|||
type: 'session.closed', |
|||
detail: JSON.stringify({ type: 'session.closed', reason: 'upstream_disconnected' }), |
|||
loggedAt: 5 |
|||
}); |
|||
|
|||
const row = recorder.rawDb |
|||
.prepare('SELECT session_id FROM events WHERE type = ?') |
|||
.get('session.closed'); |
|||
expect(row).toEqual({ session_id: 'session-1' }); |
|||
}); |
|||
|
|||
describe('WAL mode', () => { |
|||
let tmpDir: string; |
|||
|
|||
afterEach(() => { |
|||
if (tmpDir) rmSync(tmpDir, { recursive: true, force: true }); |
|||
}); |
|||
|
|||
it('enables WAL journal mode for a real file-backed database', () => { |
|||
// SQLite silently keeps ':memory:' databases in 'memory' journal mode
|
|||
// regardless of a WAL pragma call, so this needs a real file path to
|
|||
// mean anything — asserting it against the ':memory:' recorder used
|
|||
// everywhere else in this file would be misleading.
|
|||
tmpDir = mkdtempSync(join(tmpdir(), 'analytics-test-')); |
|||
const recorder = new SqliteAnalyticsRecorder(join(tmpDir, 'analytics.db')); |
|||
expect(recorder.rawDb.pragma('journal_mode', { simple: true })).toBe('wal'); |
|||
recorder.close(); |
|||
}); |
|||
}); |
|||
}); |
|||
@ -0,0 +1,198 @@ |
|||
import Database from 'better-sqlite3'; |
|||
import { mkdirSync } from 'node:fs'; |
|||
import { dirname } from 'node:path'; |
|||
|
|||
/** |
|||
* Recording sink for the realtime session relay (see docs/ANALYTICS.md). |
|||
* Synchronous and void-returning to match `better-sqlite3`'s own synchronous |
|||
* API — every call site in `session.ts` stays fire-and-forget with no |
|||
* `await`/error-handling threaded through the session's hot path. |
|||
*/ |
|||
export interface AnalyticsRecorder { |
|||
sessionStarted(params: { |
|||
sessionId: string; |
|||
model: string; |
|||
voice: string | undefined; |
|||
startedAt: number; // epoch ms
|
|||
}): void; |
|||
|
|||
sessionEnded(params: { sessionId: string; endedAt: number; reason: string }): void; |
|||
|
|||
messageLogged(params: { |
|||
sessionId: string; |
|||
role: 'user' | 'assistant'; |
|||
text: string; |
|||
loggedAt: number; |
|||
}): void; |
|||
|
|||
toolCallLogged(params: { |
|||
sessionId: string; |
|||
callId: string; |
|||
name: string; |
|||
arguments: string; // raw JSON string, as received on the wire
|
|||
output: string; // raw JSON string sent back as tool.result
|
|||
durationMs: number; |
|||
loggedAt: number; |
|||
}): void; |
|||
|
|||
/** |
|||
* `sessionId` is nullable: a validation error can occur before |
|||
* `session.start` completes, when no `sessions` row exists yet to |
|||
* reference. |
|||
*/ |
|||
eventLogged(params: { |
|||
sessionId: string | null; |
|||
type: 'error' | 'session.closed'; |
|||
detail: string; |
|||
loggedAt: number; |
|||
}): void; |
|||
} |
|||
|
|||
const SCHEMA_SQL = ` |
|||
CREATE TABLE IF NOT EXISTS sessions ( |
|||
id TEXT PRIMARY KEY, |
|||
model TEXT NOT NULL, |
|||
voice TEXT, |
|||
started_at INTEGER NOT NULL, |
|||
ended_at INTEGER, |
|||
end_reason TEXT |
|||
); |
|||
|
|||
CREATE TABLE IF NOT EXISTS messages ( |
|||
id INTEGER PRIMARY KEY AUTOINCREMENT, |
|||
session_id TEXT NOT NULL REFERENCES sessions(id), |
|||
role TEXT NOT NULL CHECK (role IN ('user', 'assistant')), |
|||
text TEXT NOT NULL, |
|||
created_at INTEGER NOT NULL |
|||
); |
|||
CREATE INDEX IF NOT EXISTS idx_messages_session_id ON messages(session_id); |
|||
|
|||
CREATE TABLE IF NOT EXISTS tool_calls ( |
|||
id INTEGER PRIMARY KEY AUTOINCREMENT, |
|||
session_id TEXT NOT NULL REFERENCES sessions(id), |
|||
call_id TEXT NOT NULL, |
|||
name TEXT NOT NULL, |
|||
arguments TEXT NOT NULL, |
|||
output TEXT NOT NULL, |
|||
duration_ms INTEGER NOT NULL, |
|||
created_at INTEGER NOT NULL |
|||
); |
|||
CREATE INDEX IF NOT EXISTS idx_tool_calls_session_id ON tool_calls(session_id); |
|||
|
|||
CREATE TABLE IF NOT EXISTS events ( |
|||
id INTEGER PRIMARY KEY AUTOINCREMENT, |
|||
session_id TEXT REFERENCES sessions(id), |
|||
type TEXT NOT NULL CHECK (type IN ('error', 'session.closed')), |
|||
detail TEXT NOT NULL, |
|||
created_at INTEGER NOT NULL |
|||
); |
|||
CREATE INDEX IF NOT EXISTS idx_events_session_id ON events(session_id); |
|||
`;
|
|||
|
|||
/** |
|||
* `better-sqlite3`-backed `AnalyticsRecorder`. Schema is created eagerly on |
|||
* construction (`CREATE TABLE IF NOT EXISTS` — no migration framework; a |
|||
* future column change is a manual addition to `SCHEMA_SQL`). Foreign keys |
|||
* are declared for documentation but deliberately not enforced (no `PRAGMA
|
|||
* foreign_keys = ON`): this is a logging sink, not a system of record, and a
|
|||
* stray write should never be silently dropped by a constraint violation. |
|||
*/ |
|||
export class SqliteAnalyticsRecorder implements AnalyticsRecorder { |
|||
private readonly db: Database.Database; |
|||
private readonly insertSession: Database.Statement; |
|||
private readonly updateSessionEnd: Database.Statement; |
|||
private readonly insertMessage: Database.Statement; |
|||
private readonly insertToolCall: Database.Statement; |
|||
private readonly insertEvent: Database.Statement; |
|||
|
|||
constructor(dbPath: string) { |
|||
// better-sqlite3 does not create the parent directory itself — on a
|
|||
// fresh checkout `data/` doesn't exist yet. No-op for ':memory:'
|
|||
// (dirname resolves to '.').
|
|||
mkdirSync(dirname(dbPath), { recursive: true }); |
|||
this.db = new Database(dbPath); |
|||
this.db.pragma('journal_mode = WAL'); |
|||
// better-sqlite3 defaults foreign_keys to ON, which would turn a stray
|
|||
// write (e.g. a mismatched session_id) into a dropped insert. This is a
|
|||
// logging sink, not a system of record — explicitly opt out so the
|
|||
// declared FKs stay documentation only, never enforcement.
|
|||
this.db.pragma('foreign_keys = OFF'); |
|||
this.db.exec(SCHEMA_SQL); |
|||
|
|||
this.insertSession = this.db.prepare( |
|||
'INSERT INTO sessions (id, model, voice, started_at) VALUES (?, ?, ?, ?)' |
|||
); |
|||
this.updateSessionEnd = this.db.prepare( |
|||
'UPDATE sessions SET ended_at = ?, end_reason = ? WHERE id = ?' |
|||
); |
|||
this.insertMessage = this.db.prepare( |
|||
'INSERT INTO messages (session_id, role, text, created_at) VALUES (?, ?, ?, ?)' |
|||
); |
|||
this.insertToolCall = this.db.prepare( |
|||
`INSERT INTO tool_calls (session_id, call_id, name, arguments, output, duration_ms, created_at)
|
|||
VALUES (?, ?, ?, ?, ?, ?, ?)` |
|||
); |
|||
this.insertEvent = this.db.prepare( |
|||
'INSERT INTO events (session_id, type, detail, created_at) VALUES (?, ?, ?, ?)' |
|||
); |
|||
} |
|||
|
|||
sessionStarted({ |
|||
sessionId, |
|||
model, |
|||
voice, |
|||
startedAt |
|||
}: Parameters<AnalyticsRecorder['sessionStarted']>[0]): void { |
|||
this.insertSession.run(sessionId, model, voice ?? null, startedAt); |
|||
} |
|||
|
|||
sessionEnded({ |
|||
sessionId, |
|||
endedAt, |
|||
reason |
|||
}: Parameters<AnalyticsRecorder['sessionEnded']>[0]): void { |
|||
this.updateSessionEnd.run(endedAt, reason, sessionId); |
|||
} |
|||
|
|||
messageLogged({ |
|||
sessionId, |
|||
role, |
|||
text, |
|||
loggedAt |
|||
}: Parameters<AnalyticsRecorder['messageLogged']>[0]): void { |
|||
this.insertMessage.run(sessionId, role, text, loggedAt); |
|||
} |
|||
|
|||
// `arguments` can't be used as a bare destructured binding name (reserved
|
|||
// in strict-mode bindings, and class bodies are always strict) — renamed
|
|||
// to `args` here.
|
|||
toolCallLogged({ |
|||
sessionId, |
|||
callId, |
|||
name, |
|||
arguments: args, |
|||
output, |
|||
durationMs, |
|||
loggedAt |
|||
}: Parameters<AnalyticsRecorder['toolCallLogged']>[0]): void { |
|||
this.insertToolCall.run(sessionId, callId, name, args, output, durationMs, loggedAt); |
|||
} |
|||
|
|||
eventLogged({ |
|||
sessionId, |
|||
type, |
|||
detail, |
|||
loggedAt |
|||
}: Parameters<AnalyticsRecorder['eventLogged']>[0]): void { |
|||
this.insertEvent.run(sessionId, type, detail, loggedAt); |
|||
} |
|||
|
|||
/** Direct row access for tests only — session.ts must only ever go through AnalyticsRecorder. */ |
|||
get rawDb(): Database.Database { |
|||
return this.db; |
|||
} |
|||
|
|||
close(): void { |
|||
this.db.close(); |
|||
} |
|||
} |
|||
Loading…
Reference in new issue