DO-NOT-MERGE: Extended logging for mute states

src/config/ConfigOptions.ts

@@ -168,6 +168,15 @@ export interface ResolvedConfigOptions extends ConfigOptions {
     enable_video: boolean;
   };
   app_prompt: boolean;
+  logging?: {
+    livekit_log_level?:
+      | "trace"
+      | "debug"
+      | "info"
+      | "warn"
+      | "error"
+      | "silent";
+  };
 }
 
 export const DEFAULT_CONFIG: ResolvedConfigOptions = {
@@ -186,4 +195,7 @@ export const DEFAULT_CONFIG: ResolvedConfigOptions = {
     enable_video: true,
   },
   app_prompt: true,
+  logging: {
+    livekit_log_level: "info",
+  },
 };

src/main.tsx

@@ -16,6 +16,7 @@ import { createRoot } from "react-dom/client";
 import "./index.css";
 import { logger } from "matrix-js-sdk/lib/logger";
 import {
+  LogLevel,
   setLogExtension as setLKLogExtension,
   setLogLevel as setLKLogLevel,
 } from "livekit-client";
@@ -25,13 +26,37 @@ import { init as initRageshake } from "./settings/rageshake";
 import { Initializer } from "./initializer";
 import { AppViewModel } from "./state/AppViewModel";
 import { globalScope } from "./state/ObservableScope";
+import { Config } from "./config/Config.ts";
 
 window.setLKLogLevel = setLKLogLevel;
 
 initRageshake().catch((e) => {
   logger.error("Failed to initialize rageshake", e);
 });
 setLKLogLevel("info");
+
+// Initialize config and set LiveKit log level accordingly
+// dev/test deployments can set the log level more verbose via config to help debugging
+Config.init()
+  .then(() => {
+    const LKLogsMapping = {
+      trace: LogLevel.trace,
+      debug: LogLevel.debug,
+      info: LogLevel.info,
+      warn: LogLevel.warn,
+      error: LogLevel.error,
+      silent: LogLevel.silent,
+    };
+    // const logLevelConfig = Config.get().logging?.livekit_log_level;
+    // DO NOT COMMIT: temporarily hardcode until we add this to config options
+    const logLevelConfig = "debug";
+
+    setLKLogLevel(LKLogsMapping[logLevelConfig ?? "info"] ?? LogLevel.info);
+  })
+  .catch((e) => {
+    logger.error("Failed to initialize config for livekit log level", e);
+  });
+
 setLKLogExtension((level, msg, context) => {
   // we pass a synthetic logger name of "livekit" to the rageshake to make it easier to read
   global.mx_rage_logger.log(level, "livekit", msg, context);

src/state/CallViewModel/CallViewModel.ts

@@ -477,9 +477,7 @@ export function createCallViewModel$(
         mediaDevices,
         muteStates,
         trackProcessorState$,
-        logger.getChild(
-          "[Publisher" + connection.transport.livekit_service_url + "]",
-        ),
+        logger.getChild(`[${connection.transport.livekit_service_url}]`),
       );
     },
     connectionManager: connectionManager,

src/state/CallViewModel/localMember/Publisher.ts

@@ -45,23 +45,26 @@ import {
  * The Publisher is also responsible for creating the media tracks.
  */
 export class Publisher {
+  private readonly logger: Logger;
+
   /**
    * Creates a new Publisher.
    * @param scope - The observable scope to use for managing the publisher.
    * @param connection - The connection to use for publishing.
    * @param devices - The media devices to use for audio and video input.
    * @param muteStates - The mute states for audio and video.
-   * @param e2eeLivekitOptions - The E2EE options to use for the LiveKit room. Use to share the same key provider across connections!.
    * @param trackerProcessorState$ - The processor state for the video track processor (e.g. background blur).
+   * @param logger - the parent logger
    */
   public constructor(
     private scope: ObservableScope,
     private connection: Pick<Connection, "livekitRoom" | "state$">, //setE2EEEnabled,
     devices: MediaDevices,
     private readonly muteStates: MuteStates,
     trackerProcessorState$: Behavior<ProcessorState>,
-    private logger: Logger,
+    logger: Logger,
   ) {
+    this.logger = logger.getChild(`[Publisher]`);
     this.logger.info("Create LiveKit room");
     const { controlledAudioDevices } = getUrlParams();
 
@@ -149,6 +152,7 @@ export class Publisher {
 
   private _publishing$ = new BehaviorSubject<boolean>(false);
   public publishing$ = this.scope.behavior(this._publishing$);
+
   /**
    *
    * @returns
@@ -233,6 +237,7 @@ export class Publisher {
    * Stops all tracks that are currently running
    */
   public stopTracks(): void {
+    this.logger.debug("stopTracks called");
     this.tracks$.value.forEach((t) => t.stop());
     this._tracks$.next([]);
   }
@@ -337,6 +342,7 @@ export class Publisher {
   private observeMuteStates(scope: ObservableScope): void {
     const lkRoom = this.connection.livekitRoom;
     this.muteStates.audio.setHandler(async (desired) => {
+      this.logger.debug(`Syncing LiveKit audio mute state to ${desired}`);
       try {
         await lkRoom.localParticipant.setMicrophoneEnabled(desired);
       } catch (e) {
@@ -345,6 +351,7 @@ export class Publisher {
       return lkRoom.localParticipant.isMicrophoneEnabled;
     });
     this.muteStates.video.setHandler(async (desired) => {
+      this.logger.debug(`Syncing LiveKit video mute state to ${desired}`);
       try {
         await lkRoom.localParticipant.setCameraEnabled(desired);
       } catch (e) {

src/state/MuteStates.test.ts

@@ -49,6 +49,7 @@ describe("MuteState", () => {
     } as unknown as MediaDevice<DeviceLabel, SelectedDevice>;
 
     const muteState = new MuteState(
+      "test-mutestate",
       testScope,
       deviceStub,
       constant(true),

src/state/MuteStates.ts

@@ -52,12 +52,14 @@ export class MuteState<Label, Selected> {
   private readonly handler$ = new BehaviorSubject(defaultHandler);
 
   public setHandler(handler: Handler): void {
+    logger.debug(`MuteState[${this.description}]: setting handler`);
     if (this.handler$.value !== defaultHandler)
       throw new Error("Multiple mute state handlers are not supported");
     this.handler$.next(handler);
   }
 
   public unsetHandler(): void {
+    logger.debug(`MuteState[${this.description}]: removing handler`);
     this.handler$.next(defaultHandler);
   }
 
@@ -77,16 +79,19 @@ export class MuteState<Label, Selected> {
         this.enabledByDefault$,
         (canControlDevices, enabledByDefault) => {
           logger.info(
-            `MuteState: canControlDevices: ${canControlDevices}, enabled by default: ${enabledByDefault}`,
+            `MuteState[${this.description}]: canControlDevices: ${canControlDevices}, enabled by default: ${enabledByDefault}`,
           );
           if (!canControlDevices) {
             logger.info(
-              `MuteState: devices connected: ${canControlDevices}, disabling`,
+              `MuteState[${this.description}]: devices connected: ${canControlDevices}, disabling`,
             );
             // We need to sync the mute state with the handler
             // to ensure nothing is beeing published.
             this.handler$.value(false).catch((err) => {
-              logger.error("MuteState-disable: handler error", err);
+              logger.error(
+                "MuteState[${this.description}] disable: handler error",
+                err,
+              );
             });
             return { enabled$: of(false), set: null, toggle: null };
           }
@@ -102,12 +107,18 @@ export class MuteState<Label, Selected> {
             let syncing = false;
 
             const sync = async (): Promise<void> => {
-              if (enabled === latestDesired) syncing = false;
-              else {
+              if (enabled === latestDesired) {
+                syncing = false;
+              } else {
                 const previouslyEnabled = enabled;
                 enabled = await firstValueFrom(
                   this.handler$.pipe(
-                    switchMap(async (handler) => handler(latestDesired)),
+                    switchMap(async (handler) => {
+                      logger.debug(
+                        `MuteState[${this.description}]: syncing to ${latestDesired}`,
+                      );
+                      return handler(latestDesired);
+                    }),
                   ),
                 );
                 if (enabled === previouslyEnabled) {
@@ -117,7 +128,10 @@ export class MuteState<Label, Selected> {
                   syncing = true;
                   sync().catch((err) => {
                     // TODO: better error handling
-                    logger.error("MuteState: handler error", err);
+                    logger.error(
+                      "MuteState[${this.description}]: handler error",
+                      err,
+                    );
                   });
                 }
               }
@@ -129,7 +143,10 @@ export class MuteState<Label, Selected> {
                 syncing = true;
                 sync().catch((err) => {
                   // TODO: better error handling
-                  logger.error("MuteState: handler error", err);
+                  logger.error(
+                    "MuteState[${this.description}]: handler error",
+                    err,
+                  );
                 });
               }
             });
@@ -158,6 +175,8 @@ export class MuteState<Label, Selected> {
   );
 
   public constructor(
+    // A description for logging purposes
+    private readonly description: string,
     private readonly scope: ObservableScope,
     private readonly device: MediaDevice<Label, Selected>,
     private readonly joined$: Observable<boolean>,
@@ -189,13 +208,15 @@ export class MuteStates {
   );
 
   public readonly audio = new MuteState(
+    "audio-mutestate",
     this.scope,
     this.mediaDevices.audioInput,
     this.joined$,
     Config.get().media_devices.enable_audio,
     constant(false),
   );
   public readonly video = new MuteState(
+    "video-mutestate",
     this.scope,
     this.mediaDevices.videoInput,
     this.joined$,