Adding more logs (#3563)

* Adding more logs

* post merge fix

* fixup merge error

* review

---------

Co-authored-by: Timo K <toger5@hotmail.de>

src/state/CallViewModel/CallViewModel.ts

@@ -241,6 +241,7 @@ export class CallViewModel {
         },
       ),
     ),
+    logger: logger,
   });
 
   private matrixLivekitMembers$ = createMatrixLivekitMembers$({
@@ -271,6 +272,7 @@ export class CallViewModel {
     trackProcessorState$: this.trackProcessorState$,
     widget,
     options: this.connectOptions$,
+    logger: logger.getChild(`[${Date.now()}]`),
   });
 
   private localRtcMembership$ = this.scope.behavior(

src/state/CallViewModel/localMember/LocalMembership.ts

@@ -22,6 +22,7 @@ import { ClientEvent, SyncState, type Room as MatrixRoom } from "matrix-js-sdk";
 import {
   BehaviorSubject,
   combineLatest,
+  distinctUntilChanged,
   fromEvent,
   map,
   type Observable,
@@ -29,8 +30,9 @@ import {
   scan,
   startWith,
   switchMap,
+  tap,
 } from "rxjs";
-import { logger as rootLogger } from "matrix-js-sdk/lib/logger";
+import { type Logger } from "matrix-js-sdk/lib/logger";
 
 import { type Behavior } from "../../Behavior";
 import { type IConnectionManager } from "../remoteMembers/ConnectionManager";
@@ -52,7 +54,7 @@ import { PosthogAnalytics } from "../../../analytics/PosthogAnalytics.ts";
 import { MatrixRTCMode } from "../../../settings/settings.ts";
 import { Config } from "../../../config/Config.ts";
 import { type Connection } from "../remoteMembers/Connection.ts";
-const logger = rootLogger.getChild("[LocalMembership]");
+
 export enum LivekitState {
   Uninitialized = "uninitialized",
   Connecting = "connecting",
@@ -61,6 +63,7 @@ export enum LivekitState {
   Disconnected = "disconnected",
   Disconnecting = "disconnecting",
 }
+
 type LocalMemberLivekitState =
   | { state: LivekitState.Error; error: string }
   | { state: LivekitState.Connected }
@@ -74,6 +77,7 @@ export enum MatrixState {
   Disconnected = "disconnected",
   Connecting = "connecting",
 }
+
 type LocalMemberMatrixState =
   | { state: MatrixState.Connected }
   | { state: MatrixState.Connecting }
@@ -106,6 +110,7 @@ interface Props {
   localTransport$: Behavior<LivekitTransport | null>;
   trackProcessorState$: Behavior<ProcessorState>;
   widget: WidgetHelpers | null;
+  logger: Logger;
 }
 
 /**
@@ -132,6 +137,7 @@ export const createLocalMembership$ = ({
   matrixRoom,
   trackProcessorState$,
   widget,
+  logger: parentLogger,
 }: Props): {
   // publisher: Publisher
   requestConnect: () => LocalMemberConnectionState;
@@ -157,6 +163,8 @@ export const createLocalMembership$ = ({
   /** @deprecated use state instead*/
   configError$: Behavior<ElementCallError | null>;
 } => {
+  const logger = parentLogger.getChild("[LocalMembership]");
+  logger.debug(`Creating local membership..`);
   const state = {
     livekit$: new BehaviorSubject<LocalMemberLivekitState>({
       state: LivekitState.Uninitialized,
@@ -178,17 +186,23 @@ export const createLocalMembership$ = ({
   const tracks$ = new BehaviorSubject<LocalTrack[]>([]);
 
   // Drop Epoch data here since we will not combine this anymore
-  const connection$ = scope.behavior(
+  const localConnection$ = scope.behavior(
-    combineLatest(
+    combineLatest([connectionManager.connections$, localTransport$]).pipe(
-      [connectionManager.connections$, localTransport$],
+      map(([connections, localTransport]) => {
-      (connections, transport) => {
+        if (localTransport === null) {
-        if (transport === null) return null;
+          return null;
+        }
         return (
           connections.value.find((connection) =>
-            areLivekitTransportsEqual(connection.transport, transport),
+            areLivekitTransportsEqual(connection.transport, localTransport),
           ) ?? null
         );
-      },
+      }),
+      tap((connection) => {
+        logger.info(
+          `Local connection updated: ${connection?.transport?.livekit_service_url}`,
+        );
+      }),
     ),
   );
   /**
@@ -219,6 +233,10 @@ export const createLocalMembership$ = ({
         startWith(null),
         map(() => matrixRTCSession.probablyLeft !== true),
       ),
+    ).pipe(
+      tap((connected) => {
+        logger.info(`Homeserver connected update: ${connected}`);
+      }),
     ),
   );
 
@@ -230,7 +248,7 @@ export const createLocalMembership$ = ({
   const connected$ = scope.behavior(
     and$(
       homeserverConnected$,
-      connection$.pipe(
+      localConnection$.pipe(
         switchMap((c) =>
           c
             ? c.state$.pipe(map((state) => state.state === "ConnectedToLkRoom"))
@@ -241,8 +259,9 @@ export const createLocalMembership$ = ({
   );
 
   const publisher$ = new BehaviorSubject<Publisher | null>(null);
-  connection$.subscribe((connection) => {
+  localConnection$.subscribe((connection) => {
     if (connection !== null && publisher$.value === null) {
+      // TODO looks strange to not change publisher if connection changes.
       publisher$.next(
         new Publisher(
           scope,
@@ -375,7 +394,7 @@ export const createLocalMembership$ = ({
   // We use matrixConnected$ rather than reconnecting$ because we want to
   // pause tracks during the initial joining sequence too until we're sure
   // that our own media is displayed on screen.
-  combineLatest([connection$, homeserverConnected$])
+  combineLatest([localConnection$, homeserverConnected$])
     .pipe(scope.bind())
     .subscribe(([connection, connected]) => {
       if (connection?.state$.value.state !== "ConnectedToLkRoom") return;
@@ -462,7 +481,7 @@ export const createLocalMembership$ = ({
    * Whether the user is currently sharing their screen.
    */
   const sharingScreen$ = scope.behavior(
-    connection$.pipe(
+    localConnection$.pipe(
       switchMap((c) =>
         c === null
           ? of(false)
@@ -483,7 +502,7 @@ export const createLocalMembership$ = ({
           // We also allow screen sharing to be toggled even if the connection
           // is still initializing or publishing tracks, because there's no
           // technical reason to disallow this. LiveKit will publish if it can.
-          void connection$.value?.livekitRoom.localParticipant
+          void localConnection$.value?.livekitRoom.localParticipant
             .setScreenShareEnabled(!sharingScreen$.value, {
               audio: true,
               selfBrowserSurface: "include",
@@ -494,7 +513,7 @@ export const createLocalMembership$ = ({
       : null;
 
   const participant$ = scope.behavior(
-    connection$.pipe(map((c) => c?.livekitRoom.localParticipant ?? null)),
+    localConnection$.pipe(map((c) => c?.livekitRoom.localParticipant ?? null)),
   );
   return {
     startTracks,
@@ -508,7 +527,7 @@ export const createLocalMembership$ = ({
     sharingScreen$,
     toggleScreenSharing,
     participant$,
-    connection$,
+    connection$: localConnection$,
   };
 };
 
@@ -532,6 +551,7 @@ interface EnterRTCSessionOptions {
  * @param rtcSession
  * @param transport
  * @param options
+ * @throws If the widget could not send ElementWidgetActions.JoinCall action.
  */
 async function enterRTCSession(
   rtcSession: MatrixRTCSession,
@@ -576,10 +596,6 @@ async function enterRTCSession(
     },
   );
   if (widget) {
-    try {
+    await widget.api.transport.send(ElementWidgetActions.JoinCall, {});
-      await widget.api.transport.send(ElementWidgetActions.JoinCall, {});
-    } catch (e) {
-      logger.error("Failed to send join action", e);
-    }
   }
 }

src/state/CallViewModel/remoteMembers/Connection.test.ts

@@ -14,7 +14,6 @@ import {
   onTestFinished,
   vi,
 } from "vitest";
-import { BehaviorSubject } from "rxjs";
 import {
   type LocalParticipant,
   type RemoteParticipant,
@@ -25,11 +24,9 @@ import {
 import fetchMock from "fetch-mock";
 import EventEmitter from "events";
 import { type IOpenIDToken } from "matrix-js-sdk";
+import { logger } from "matrix-js-sdk/lib/logger";
 
-import type {
+import type { LivekitTransport } from "matrix-js-sdk/lib/matrixrtc";
-  CallMembership,
-  LivekitTransport,
-} from "matrix-js-sdk/lib/matrixrtc";
 import {
   Connection,
   type ConnectionOpts,
@@ -39,6 +36,7 @@ import {
 import { ObservableScope } from "../../ObservableScope.ts";
 import { type OpenIDClientParts } from "../../../livekit/openIDSFU.ts";
 import { FailToGetOpenIdToken } from "../../../utils/errors.ts";
+
 let testScope: ObservableScope;
 
 let client: MockedObject<OpenIDClientParts>;
@@ -49,9 +47,9 @@ let localParticipantEventEmiter: EventEmitter;
 let fakeLocalParticipant: MockedObject<LocalParticipant>;
 
 let fakeRoomEventEmiter: EventEmitter;
-let fakeMembershipsFocusMap$: BehaviorSubject<
+// let fakeMembershipsFocusMap$: BehaviorSubject<
-  { membership: CallMembership; transport: LivekitTransport }[]
+//   { membership: CallMembership; transport: LivekitTransport }[]
->;
+// >;
 
 const livekitFocus: LivekitTransport = {
   livekit_alias: "!roomID:example.org",
@@ -70,9 +68,6 @@ function setupTest(): void {
     }),
     getDeviceId: vi.fn().mockReturnValue("ABCDEF"),
   } as unknown as OpenIDClientParts);
-  fakeMembershipsFocusMap$ = new BehaviorSubject<
-    { membership: CallMembership; transport: LivekitTransport }[]
-  >([]);
 
   localParticipantEventEmiter = new EventEmitter();
 
@@ -131,7 +126,7 @@ function setupRemoteConnection(): Connection {
 
   fakeLivekitRoom.connect.mockResolvedValue(undefined);
 
-  return new Connection(opts);
+  return new Connection(opts, logger);
 }
 
 afterEach(() => {
@@ -150,7 +145,7 @@ describe("Start connection states", () => {
       scope: testScope,
       livekitRoomFactory: () => fakeLivekitRoom,
     };
-    const connection = new Connection(opts);
+    const connection = new Connection(opts, logger);
 
     expect(connection.state$.getValue().state).toEqual("Initialized");
   });
@@ -166,7 +161,7 @@ describe("Start connection states", () => {
       livekitRoomFactory: () => fakeLivekitRoom,
     };
 
-    const connection = new Connection(opts, undefined);
+    const connection = new Connection(opts, logger);
 
     const capturedStates: ConnectionState[] = [];
     const s = connection.state$.subscribe((value) => {
@@ -218,7 +213,7 @@ describe("Start connection states", () => {
       livekitRoomFactory: () => fakeLivekitRoom,
     };
 
-    const connection = new Connection(opts, undefined);
+    const connection = new Connection(opts, logger);
 
     const capturedStates: ConnectionState[] = [];
     const s = connection.state$.subscribe((value) => {
@@ -274,7 +269,7 @@ describe("Start connection states", () => {
       livekitRoomFactory: () => fakeLivekitRoom,
     };
 
-    const connection = new Connection(opts, undefined);
+    const connection = new Connection(opts, logger);
 
     const capturedStates: ConnectionState[] = [];
     const s = connection.state$.subscribe((value) => {

src/state/CallViewModel/remoteMembers/Connection.ts

@@ -98,6 +98,7 @@ export class Connection {
   // TODO dont make this throw and instead store a connection error state in this class?
   // TODO consider an autostart pattern...
   public async start(): Promise<void> {
+    this.logger.debug("Starting Connection");
     this.stopped = false;
     try {
       this._state$.next({
@@ -145,6 +146,7 @@ export class Connection {
         livekitConnectionState$: connectionStateObserver(this.livekitRoom),
       });
     } catch (error) {
+      this.logger.debug(`Failed to connect to LiveKit room: ${error}`);
       this._state$.next({
         state: "FailedToStart",
         error: error instanceof Error ? error : new Error(`${error}`),
@@ -169,6 +171,9 @@ export class Connection {
    * If the connection is already stopped, this is a no-op.
    */
   public async stop(): Promise<void> {
+    this.logger.debug(
+      `Stopping connection to ${this.transport.livekit_service_url}`,
+    );
     if (this.stopped) return;
     await this.livekitRoom.disconnect();
     this._state$.next({
@@ -195,15 +200,18 @@ export class Connection {
   private readonly client: OpenIDClientParts;
   public readonly livekitRoom: LivekitRoom;
 
+  private readonly logger: Logger;
+
   /**
    * Creates a new connection to a matrix RTC LiveKit backend.
    *
-   * @param livekitRoom - LiveKit room instance to use.
    * @param opts - Connection options {@link ConnectionOpts}.
    *
+   * @param logger
    */
-  public constructor(opts: ConnectionOpts, logger?: Logger) {
+  public constructor(opts: ConnectionOpts, logger: Logger) {
-    logger?.info(
+    this.logger = logger.getChild("[Connection]");
+    this.logger.info(
       `[Connection] Creating new connection to ${opts.transport.livekit_service_url} ${opts.transport.livekit_alias}`,
     );
     const { transport, client, scope } = opts;
@@ -223,15 +231,17 @@ export class Connection {
         ],
       }).pipe(
         map((participants) => {
-          const partsFiltered = participants.filter(
+          return participants.filter(
             (participant) => participant.getTrackPublications().length > 0,
           );
-          return partsFiltered;
         }),
       ),
       [],
     );
 
-    scope.onEnd(() => void this.stop());
+    scope.onEnd(() => {
+      this.logger.info(`Connection scope ended, stopping connection`);
+      void this.stop();
+    });
   }
 }

src/state/CallViewModel/remoteMembers/ConnectionManager.test.ts

@@ -9,6 +9,7 @@ import { afterEach, beforeEach, describe, expect, test, vi } from "vitest";
 import { BehaviorSubject } from "rxjs";
 import { type LivekitTransport } from "matrix-js-sdk/lib/matrixrtc";
 import { type Participant as LivekitParticipant } from "livekit-client";
+import { logger } from "matrix-js-sdk/lib/logger";
 
 import { Epoch, ObservableScope } from "../../ObservableScope.ts";
 import {
@@ -78,6 +79,7 @@ describe("connections$ stream", () => {
         inputTransports$: behavior("a", {
           a: new Epoch([TRANSPORT_1, TRANSPORT_2], 0),
         }),
+        logger: logger,
       });
 
       expectObservable(connections$).toBe("a", {
@@ -119,6 +121,7 @@ describe("connections$ stream", () => {
           e: new Epoch([TRANSPORT_1], 4),
           f: new Epoch([TRANSPORT_1, TRANSPORT_2], 5),
         }),
+        logger: logger,
       });
 
       expectObservable(connections$).toBe("xxxxxa", {
@@ -158,6 +161,7 @@ describe("connections$ stream", () => {
           b: new Epoch([TRANSPORT_1, TRANSPORT_2], 1),
           c: new Epoch([TRANSPORT_1], 2),
         }),
+        logger: logger,
       });
 
       expectObservable(connections$).toBe("xab", {
@@ -272,6 +276,7 @@ describe("connectionManagerData$ stream", () => {
         inputTransports$: behavior("a", {
           a: new Epoch([TRANSPORT_1, TRANSPORT_2], 0),
         }),
+        logger,
       });
 
       expectObservable(connectionManagerData$).toBe("abcd", {

src/state/CallViewModel/remoteMembers/ConnectionManager.ts

@@ -13,8 +13,8 @@ import {
   type LivekitTransport,
   type ParticipantId,
 } from "matrix-js-sdk/lib/matrixrtc";
-import { BehaviorSubject, combineLatest, map, of, switchMap } from "rxjs";
+import { BehaviorSubject, combineLatest, map, of, switchMap, tap } from "rxjs";
-import { logger as rootLogger } from "matrix-js-sdk/lib/logger";
+import { type Logger } from "matrix-js-sdk/lib/logger";
 import { type LocalParticipant, type RemoteParticipant } from "livekit-client";
 
 import { type Behavior } from "../../Behavior.ts";
@@ -91,6 +91,7 @@ interface Props {
   scope: ObservableScope;
   connectionFactory: ConnectionFactory;
   inputTransports$: Behavior<Epoch<LivekitTransport[]>>;
+  logger: Logger;
 }
 // TODO - write test for scopes (do we really need to bind scope)
 export interface IConnectionManager {
@@ -116,8 +117,9 @@ export function createConnectionManager$({
   scope,
   connectionFactory,
   inputTransports$,
+  logger: parentLogger,
 }: Props): IConnectionManager {
-  const logger = rootLogger.getChild("[ConnectionManager]");
+  const logger = parentLogger.getChild("[ConnectionManager]");
 
   const running$ = new BehaviorSubject(true);
   scope.onEnd(() => running$.next(false));
@@ -137,6 +139,11 @@ export function createConnectionManager$({
         transports.mapInner((transport) => (running ? transport : [])),
       ),
       map((transports) => transports.mapInner(removeDuplicateTransports)),
+      tap(({ value: transports }) => {
+        logger.trace(
+          `Managing transports: ${transports.map((t) => t.livekit_service_url).join(", ")}`,
+        );
+      }),
     ),
   );
 
@@ -154,6 +161,7 @@ export function createConnectionManager$({
             };
         },
         (scope, _data$, serviceUrl, alias) => {
+          logger.debug(`Creating connection to ${serviceUrl} (${alias})`);
           const connection = connectionFactory.createConnection(
             {
               type: "livekit",

src/state/CallViewModel/remoteMembers/integration.test.ts

@@ -11,6 +11,7 @@ import { type Room as LivekitRoom } from "livekit-client";
 import EventEmitter from "events";
 import fetchMock from "fetch-mock";
 import { type LivekitTransport } from "matrix-js-sdk/lib/matrixrtc";
+import { logger } from "matrix-js-sdk/lib/logger";
 
 import {
   type Epoch,
@@ -120,6 +121,7 @@ test("bob, carl, then bob joining no tracks yet", () => {
       scope: testScope,
       connectionFactory: ecConnectionFactory,
       inputTransports$: membershipsAndTransports.transports$,
+      logger: logger,
     });
 
     const matrixLivekitItems$ = createMatrixLivekitMembers$({

src/state/ObservableScope.test.ts

@@ -6,7 +6,7 @@ Please see LICENSE in the repository root for full details.
 */
 
 import { describe, expect, it } from "vitest";
-import { BehaviorSubject, combineLatest, of, Subject } from "rxjs";
+import { BehaviorSubject, combineLatest, Subject } from "rxjs";
 import { logger } from "matrix-js-sdk/lib/logger";
 
 import {

src/state/ObservableScope.ts

@@ -21,7 +21,6 @@ import {
 } from "rxjs";
 
 import { type Behavior } from "./Behavior";
-import { logger } from "matrix-js-sdk/lib/logger";
 
 type MonoTypeOperator = <T>(o: Observable<T>) => Observable<T>;