add more debug logs and more granular logger instances

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/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,112 @@
+import * as loglevel from 'loglevel';
+import { afterEach, describe, expect, it, vi } from 'vitest';
+import {
+  LogLevel,
+  LoggerNames,
+  type LogExtension,
+  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);
+  });
+});