diff --git a/LOGGING.md b/LOGGING.md new file mode 100644 index 0000000000..e3faf461e4 --- /dev/null +++ b/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. diff --git a/src/logger.test.ts b/src/logger.test.ts new file mode 100644 index 0000000000..ad8d41bdbd --- /dev/null +++ b/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(); + 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(); + 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(); + hookBase(LoggerNames.Engine, extension); + setLogLevel(LogLevel.info, LoggerNames.Engine); + + let current: Record = { 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(); + hookBase(LoggerNames.Signal, extension); + setLogLevel(LogLevel.info, LoggerNames.Signal); + + const log = getLogger(LoggerNames.Signal); + log.info('raw'); + + expect(extension).toHaveBeenCalledWith(LogLevel.info, 'raw', undefined); + }); +}); diff --git a/src/logger.ts b/src/logger.ts index 2b4e7a9946..f4e3177641 100644 --- a/src/logger.ts +++ b/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,6 +40,8 @@ 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)); @@ -44,13 +49,82 @@ 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; + 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) {