Improve logging foundation

LOGGING.md

@@ -0,0 +1,61 @@
+# Logging conventions
+
+This SDK uses [loglevel](https://github.com/pimterry/loglevel) via a thin
+wrapper in [`src/logger.ts`](src/logger.ts). Each subsystem gets its own
+named logger (see `LoggerNames`) so users can raise verbosity per area via
+`setLogLevel(level, loggerName)`.
+
+## Level rubric
+
+- **error** — failure surfaced to the user / unrecoverable. Gave up
+  reconnecting, publish rejected by server, decode permanently failed.
+- **warn** — recoverable anomaly or automatic retry. ICE restart, signal
+  reconnect starting, token refresh retryable failure, unexpected-but-
+  handled server message.
+- **info** — exactly one log per meaningful lifecycle transition:
+  `connecting` / `connected` / `reconnecting (attempt N)` / `reconnected` /
+  `disconnected (reason)`, track `published` / `unpublished` /
+  `subscribed` / `unsubscribed`, permission changes, region switched,
+  e2ee enabled/disabled, signal (re)connected, major engine state
+  transitions. Nothing that can fire more than about once per second
+  under normal use.
+- **debug** — everything else: individual signal messages, per-ICE-
+  candidate, SDP, DTX/simulcast/codec negotiation, data channel
+  lifecycle, reconnection internal states, timing details.
+- **trace** — reserved for deliberate deep dives; unused by default.
+
+## Structured context
+
+Each class passes a structured `logContext` object to every log call so
+consumers wired up via `setLogExtension` receive full metadata for
+ingestion. The display-oriented keys listed in `DISPLAY_KEYS`
+(`room`, `roomID`, `participant`, `participantID`, `trackID`, `source`,
+`target`, `transport`, `reconnectAttempt`, `region`) are additionally
+rendered as a bracketed prefix on the human-readable log message, so
+they remain visible in browser devtools without having to expand the
+structured object.
+
+### Binding context to a logger
+
+Prefer creating the named logger with a context provider once, then
+passing only call-site-specific extras:
+
+```ts
+// in a class constructor
+this.log = getLogger(LoggerNames.Engine, () => this.logContext);
+
+// at call sites
+this.log.debug('got ICE candidate from peer', { candidate, target });
+// devtools: [room=foo participant=alice target=PUBLISHER] got ICE candidate from peer
+// setLogExtension: { room: 'foo', participant: 'alice', ..., candidate, target }
+```
+
+The context provider is invoked on every call, so updates to `logContext`
+are reflected automatically.
+
+### Extending `DISPLAY_KEYS`
+
+Add a key to `DISPLAY_KEYS` only when it meaningfully narrows down
+*which* entity a log line refers to (an ID, a transport target, a
+reconnect attempt number). Metrics, timings, and payload details belong
+in the structured context but not in the message prefix.

src/logger.test.ts

@@ -0,0 +1,112 @@
+import * as loglevel from 'loglevel';
+import { afterEach, describe, expect, it, vi } from 'vitest';
+import {
+  type LogExtension,
+  LogLevel,
+  LoggerNames,
+  type StructuredLogger,
+  formatDisplayContext,
+  getLogger,
+  setLogExtension,
+  setLogLevel,
+} from './logger';
+
+describe('formatDisplayContext', () => {
+  it('returns an empty string for undefined or empty input', () => {
+    expect(formatDisplayContext(undefined)).toBe('');
+    expect(formatDisplayContext({})).toBe('');
+  });
+
+  it('renders only recognised display keys, skipping undefined/null/empty', () => {
+    const out = formatDisplayContext({
+      room: 'foo',
+      roomID: undefined,
+      participant: 'alice',
+      participantID: '',
+      trackID: null,
+      source: 'camera',
+      irrelevant: 'should-not-show',
+    });
+    expect(out).toBe('[room=foo participant=alice source=camera]');
+  });
+
+  it('preserves the canonical key ordering regardless of input order', () => {
+    const a = formatDisplayContext({ trackID: 'T', room: 'R', participant: 'P' });
+    const b = formatDisplayContext({ participant: 'P', trackID: 'T', room: 'R' });
+    expect(a).toBe(b);
+    expect(a).toBe('[room=R participant=P trackID=T]');
+  });
+
+  it('handles non-string values by stringifying them', () => {
+    expect(formatDisplayContext({ reconnectAttempt: 3 })).toBe('[reconnectAttempt=3]');
+  });
+});
+
+describe('getLogger with context provider', () => {
+  afterEach(() => {
+    setLogLevel(LogLevel.info);
+  });
+
+  const hookBase = (name: LoggerNames, extension: LogExtension) => {
+    const base = loglevel.getLogger(name) as StructuredLogger;
+    setLogExtension(extension, base);
+  };
+
+  it('prepends a context prefix to the message and merges context for extensions', () => {
+    const extension = vi.fn<LogExtension>();
+    hookBase(LoggerNames.Default, extension);
+    setLogLevel(LogLevel.debug, LoggerNames.Default);
+
+    const log = getLogger(LoggerNames.Default, () => ({
+      room: 'foo',
+      participant: 'alice',
+    }));
+    log.debug('hello world', { extra: 1 });
+
+    const debugCalls = extension.mock.calls.filter((c) => c[0] === LogLevel.debug);
+    expect(debugCalls).toHaveLength(1);
+    const [level, msg, ctx] = debugCalls[0];
+    expect(level).toBe(LogLevel.debug);
+    expect(msg).toBe('[room=foo participant=alice] hello world');
+    expect(ctx).toEqual({ room: 'foo', participant: 'alice', extra: 1 });
+  });
+
+  it('omits the prefix when the bound context has no display keys', () => {
+    const extension = vi.fn<LogExtension>();
+    hookBase(LoggerNames.Room, extension);
+    setLogLevel(LogLevel.info, LoggerNames.Room);
+
+    const log = getLogger(LoggerNames.Room, () => ({ irrelevant: 'x' }));
+    log.info('plain');
+
+    expect(extension).toHaveBeenCalledWith(LogLevel.info, 'plain', { irrelevant: 'x' });
+  });
+
+  it('reflects dynamic changes to the bound context on every call', () => {
+    const extension = vi.fn<LogExtension>();
+    hookBase(LoggerNames.Engine, extension);
+    setLogLevel(LogLevel.info, LoggerNames.Engine);
+
+    let current: Record<string, string> = { room: 'r1' };
+    const log = getLogger(LoggerNames.Engine, () => current);
+
+    log.info('first');
+    current = { room: 'r2', participant: 'bob' };
+    log.info('second');
+
+    const infos = extension.mock.calls.filter((c) => c[0] === LogLevel.info);
+    expect(infos[0][1]).toBe('[room=r1] first');
+    expect(infos[1][1]).toBe('[room=r2 participant=bob] second');
+  });
+
+  it('returns an unwrapped logger when no context provider is supplied', () => {
+    const extension = vi.fn<LogExtension>();
+    hookBase(LoggerNames.Signal, extension);
+    setLogLevel(LogLevel.info, LoggerNames.Signal);
+
+    const log = getLogger(LoggerNames.Signal);
+    log.info('raw');
+
+    expect(extension).toHaveBeenCalledWith(LogLevel.info, 'raw', undefined);
+  });
+});

src/logger.ts

@@ -22,6 +22,9 @@ export enum LoggerNames {
   PCTransport = 'livekit-pc-transport',
   E2EE = 'lk-e2ee',
   DataTracks = 'livekit-data-tracks',
+  Region = 'livekit-region',
+  Reconnection = 'livekit-reconnection',
+  ICE = 'livekit-ice',
 }
 
 type LogLevelString = keyof typeof LogLevel;
@@ -37,20 +40,91 @@ export type StructuredLogger = log.Logger & {
   getLevel: () => number;
 };
 
+export type ContextProvider = () => object | undefined;
+
 let livekitLogger = log.getLogger('livekit');
 const livekitLoggers = Object.values(LoggerNames).map((name) => log.getLogger(name));
 
 livekitLogger.setDefaultLevel(LogLevel.info);
 
 export default livekitLogger as StructuredLogger;
 
+/**
+ * Keys lifted from a logger's bound context into the human-readable log
+ * message prefix. Ordering here defines ordering in the rendered prefix.
+ * Values that are `undefined` or empty strings are skipped.
+ */
+const DISPLAY_KEYS = [
+  'room',
+  'roomID',
+  'participant',
+  'participantID',
+  'trackID',
+  'source',
+  'target',
+  'transport',
+  'reconnectAttempt',
+  'region',
+] as const;
+
+/**
+ * Render the subset of `ctx` listed in `DISPLAY_KEYS` as a bracketed prefix
+ * suitable for prepending to a log message. Returns an empty string when
+ * no display keys are present. Pure function — safe to unit test directly.
+ */
+export function formatDisplayContext(ctx: object | undefined): string {
+  if (!ctx) return '';
+  const parts: string[] = [];
+  const record = ctx as Record<string, unknown>;
+  for (const key of DISPLAY_KEYS) {
+    const value = record[key];
+    if (value === undefined || value === null || value === '') continue;
+    parts.push(`${key}=${String(value)}`);
+  }
+  return parts.length === 0 ? '' : `[${parts.join(' ')}]`;
+}
+
 /**
  * @internal
+ *
+ * Get a named logger. When `ctxFn` is supplied, every log call
+ * automatically:
+ * 1. prepends a `[key=value ...]` prefix derived from `ctxFn()` to the
+ *    message string, so identifiers are visible in browser devtools
+ *    without expanding the structured context object, and
+ * 2. merges `ctxFn()` into the structured context passed to any
+ *    `setLogExtension` consumer, so ingestion pipelines continue to
+ *    receive the full metadata unchanged.
  */
-export function getLogger(name: string) {
+export function getLogger(name: string, ctxFn?: ContextProvider) {
   const logger = log.getLogger(name);
   logger.setDefaultLevel(livekitLogger.getLevel());
-  return logger as StructuredLogger;
+  if (!ctxFn) {
+    return logger as StructuredLogger;
+  }
+  return wrapWithContext(logger as StructuredLogger, ctxFn);
+}
+
+function wrapWithContext(base: StructuredLogger, ctxFn: ContextProvider): StructuredLogger {
+  type LogMethod = 'trace' | 'debug' | 'info' | 'warn' | 'error';
+  // Resolve the underlying method on every call so that later
+  // setLogExtension installations (which replace the base logger's
+  // methods via loglevel's methodFactory) are picked up.
+  const wrap = (method: LogMethod) => (msg: string, extra?: object) => {
+    const ctx = ctxFn();
+    const prefix = formatDisplayContext(ctx);
+    const finalMsg = prefix ? `${prefix} ${msg}` : msg;
+    const merged = ctx || extra ? { ...ctx, ...extra } : undefined;
+    base[method](finalMsg, merged);
+  };
+
+  const proxy = Object.create(base) as StructuredLogger;
+  proxy.trace = wrap('trace');
+  proxy.debug = wrap('debug');
+  proxy.info = wrap('info');
+  proxy.warn = wrap('warn');
+  proxy.error = wrap('error');
+  return proxy;
 }
 
 export function setLogLevel(level: LogLevel | LogLevelString, loggerName?: LoggerNames) {