Improve logging foundation (#1907)

Author: lukasIO

.changeset/tough-stingrays-scream.md

@@ -0,0 +1,5 @@
+---
+"livekit-client": patch
+---
+
+chore: improve logging foundation for implicit context retrieval

LOGGING.md

@@ -0,0 +1,51 @@
+# 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.
+
+### 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: got ICE candidate from peer, { room: 'foo', participant: 'alice', ..., candidate, target }
+// setLogExtension: { room: 'foo', participant: 'alice', ..., candidate, target }
+```
+
+The context provider is invoked on every call, so updates to `logContext`
+are reflected automatically.
+
+

src/api/SignalClient.ts

@@ -247,8 +247,8 @@ export class SignalClient {
   private useV0SignalPath = false;
 
   constructor(useJSON: boolean = false, loggerOptions: LoggerOptions = {}) {
-    this.log = getLogger(loggerOptions.loggerName ?? LoggerNames.Signal);
     this.loggerContextCb = loggerOptions.loggerContextCb;
+    this.log = getLogger(loggerOptions.loggerName ?? LoggerNames.Signal, () => this.logContext);
     this.useJSON = useJSON;
     this.requestQueue = new AsyncQueue();
     this.queuedRequests = [];
@@ -284,10 +284,7 @@ export class SignalClient {
     reason?: ReconnectReason,
   ): Promise<ReconnectResponse | undefined> {
     if (!this.options) {
-      this.log.warn(
-        'attempted to reconnect without signal options being set, ignoring',
-        this.logContext,
-      );
+      this.log.warn('attempted to reconnect without signal options being set, ignoring');
       return;
     }
     this.state = SignalConnectionState.RECONNECTING;
@@ -377,10 +374,9 @@ export class SignalClient {
         if (redactedUrl.searchParams.has('access_token')) {
           redactedUrl.searchParams.set('access_token', '<redacted>');
         }
-        this.log.debug(`connecting to ${redactedUrl}`, {
+        this.log.info(`signal connecting to ${redactedUrl}`, {
           reconnect: opts.reconnect,
           reconnectReason: opts.reconnectReason,
-          ...this.logContext,
         });
         if (this.ws) {
           await this.close(false);
@@ -399,7 +395,6 @@ export class SignalClient {
               }
               if (closeInfo.closeCode !== 1000) {
                 this.log.warn(`websocket closed`, {
-                  ...this.logContext,
                   reason: closeInfo.reason,
                   code: closeInfo.closeCode,
                   wasClean: closeInfo.closeCode === 1000,
@@ -466,7 +461,6 @@ export class SignalClient {
 
             if (this.pingTimeoutDuration && this.pingTimeoutDuration > 0) {
               this.log.debug('ping config', {
-                ...this.logContext,
                 timeout: this.pingTimeoutDuration,
                 interval: this.pingIntervalDuration,
               });
@@ -555,7 +549,7 @@ export class SignalClient {
         await Promise.race([closePromise, sleep(MAX_WS_CLOSE_TIME)]);
       }
     } catch (e) {
-      this.log.debug('websocket error while closing', { ...this.logContext, error: e });
+      this.log.debug('websocket error while closing', { error: e });
     } finally {
       if (updateState) {
         this.state = SignalConnectionState.DISCONNECTED;
@@ -566,7 +560,7 @@ export class SignalClient {
 
   // initial offer after joining
   sendOffer(offer: RTCSessionDescriptionInit, offerId: number) {
-    this.log.debug('sending offer', { ...this.logContext, offerSdp: offer.sdp });
+    this.log.debug('sending offer', { offerSdp: offer.sdp });
     this.sendRequest({
       case: 'offer',
       value: toProtoSessionDescription(offer, offerId),
@@ -575,15 +569,15 @@ export class SignalClient {
 
   // answer a server-initiated offer
   sendAnswer(answer: RTCSessionDescriptionInit, offerId: number) {
-    this.log.debug('sending answer', { ...this.logContext, answerSdp: answer.sdp });
+    this.log.debug('sending answer', { answerSdp: answer.sdp });
     return this.sendRequest({
       case: 'answer',
       value: toProtoSessionDescription(answer, offerId),
     });
   }
 
   sendIceCandidate(candidate: RTCIceCandidateInit, target: SignalTarget) {
-    this.log.debug('sending ice candidate', { ...this.logContext, candidate });
+    this.log.debug('sending ice candidate', { candidate });
     return this.sendRequest({
       case: 'trickle',
       value: new TrickleRequest({
@@ -768,10 +762,7 @@ export class SignalClient {
       return;
     }
     if (!this.streamWriter) {
-      this.log.error(
-        `cannot send signal request before connected, type: ${message?.case}`,
-        this.logContext,
-      );
+      this.log.error(`cannot send signal request before connected, type: ${message?.case}`);
       return;
     }
     const req = new SignalRequest({ message });
@@ -783,14 +774,14 @@ export class SignalClient {
         await this.streamWriter.write(req.toBinary());
       }
     } catch (e) {
-      this.log.error('error sending signal message', { ...this.logContext, error: e });
+      this.log.error('error sending signal message', { error: e });
     }
   }
 
   private handleSignalResponse(res: SignalResponse) {
     const msg = res.message;
     if (msg == undefined) {
-      this.log.debug('received unsupported message', this.logContext);
+      this.log.debug('received unsupported message');
       return;
     }
 
@@ -899,7 +890,7 @@ export class SignalClient {
         this.onDataTrackSubscriberHandles(msg.value);
       }
     } else {
-      this.log.debug('unsupported message', { ...this.logContext, msgCase: msg.case });
+      this.log.debug('unsupported message', { msgCase: msg.case });
     }
 
     if (!pingHandled) {
@@ -920,14 +911,14 @@ export class SignalClient {
     if (this.state === SignalConnectionState.DISCONNECTED) return;
     const onCloseCallback = this.onClose;
     await this.close(undefined, reason);
-    this.log.debug(`websocket connection closed: ${reason}`, { ...this.logContext, reason });
+    this.log.info(`websocket connection closed: ${reason}`, { reason });
     if (onCloseCallback) {
       onCloseCallback(reason);
     }
   }
 
   private handleWSError(error: unknown) {
-    this.log.error('websocket error', { ...this.logContext, error });
+    this.log.error('websocket error', { error });
   }
 
   /**
@@ -937,15 +928,14 @@ export class SignalClient {
   private resetPingTimeout() {
     this.clearPingTimeout();
     if (!this.pingTimeoutDuration) {
-      this.log.warn('ping timeout duration not set', this.logContext);
+      this.log.warn('ping timeout duration not set');
       return;
     }
     this.pingTimeout = CriticalTimers.setTimeout(() => {
       this.log.warn(
         `ping timeout triggered. last pong received at: ${new Date(
           Date.now() - this.pingTimeoutDuration! * 1000,
         ).toUTCString()}`,
-        this.logContext,
       );
       this.handleOnClose('ping timeout');
     }, this.pingTimeoutDuration * 1000);
@@ -964,17 +954,17 @@ export class SignalClient {
     this.clearPingInterval();
     this.resetPingTimeout();
     if (!this.pingIntervalDuration) {
-      this.log.warn('ping interval duration not set', this.logContext);
+      this.log.warn('ping interval duration not set');
       return;
     }
-    this.log.debug('start ping interval', this.logContext);
+    this.log.debug('start ping interval');
     this.pingInterval = CriticalTimers.setInterval(() => {
       this.sendPing();
     }, this.pingIntervalDuration * 1000);
   }
 
   private clearPingInterval() {
-    this.log.debug('clearing ping interval', this.logContext);
+    this.log.debug('clearing ping interval');
     this.clearPingTimeout();
     if (this.pingInterval) {
       CriticalTimers.clearInterval(this.pingInterval);
@@ -994,6 +984,7 @@ export class SignalClient {
     firstMessage?: SignalResponse,
   ) {
     this.state = SignalConnectionState.CONNECTED;
+    this.log.info('signal connected');
     clearTimeout(timeoutHandle);
     this.startPingInterval();
     this.startReadingLoop(connection.readable.getReader(), firstMessage);
@@ -1031,10 +1022,7 @@ export class SignalClient {
         };
       } else {
         // in reconnecting, any message received means signal reconnected and we still need to process it
-        this.log.debug(
-          'declaring signal reconnected without reconnect response received',
-          this.logContext,
-        );
+        this.log.debug('declaring signal reconnected without reconnect response received');
         return {
           isValid: true,
           response: undefined,

src/logger.test.ts

@@ -0,0 +1,61 @@
+import * as loglevel from 'loglevel';
+import { afterEach, describe, expect, it, vi } from 'vitest';
+import {
+  type LogExtension,
+  LogLevel,
+  LoggerNames,
+  type StructuredLogger,
+  getLogger,
+  setLogExtension,
+  setLogLevel,
+} from './logger';
+
+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('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][2]).toEqual({ room: 'r1' });
+    expect(infos[1][2]).toEqual({ room: 'r2', participant: 'bob' });
+  });
+
+  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

@@ -37,7 +37,9 @@ export type StructuredLogger = log.Logger & {
   getLevel: () => number;
 };
 
-let livekitLogger = log.getLogger('livekit');
+export type ContextProvider = () => object | undefined;
+
+let livekitLogger = log.getLogger(LoggerNames.Default);
 const livekitLoggers = Object.values(LoggerNames).map((name) => log.getLogger(name));
 
 livekitLogger.setDefaultLevel(LogLevel.info);
@@ -46,11 +48,43 @@ export default livekitLogger as StructuredLogger;
 
 /**
  * @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 merged = ctx || extra ? { ...ctx, ...extra } : undefined;
+    base[method](msg, 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) {
@@ -93,4 +127,4 @@ export function setLogExtension(extension: LogExtension, logger?: StructuredLogg
   });
 }
 
-export const workerLogger = log.getLogger('lk-e2ee') as StructuredLogger;
+export const workerLogger = log.getLogger(LoggerNames.E2EE) as StructuredLogger;