Log remote participant and track events per LiveKit connection

Rageshakes contained nothing about the state of remote tracks, so a tile
showing the wrong mute or video state for a member could not be
diagnosed. Log connect/disconnect, publish/unpublish, subscribe/
unsubscribe, subscription failures, remote mute/unmute and stream state
changes on each Connection's logger, and remove the listeners when the
connection scope ends.

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

@@ -19,14 +19,17 @@ import {
 import {
   type LocalParticipant,
   type RemoteParticipant,
+  type RemoteTrack,
+  type RemoteTrackPublication,
   type Room as LivekitRoom,
   RoomEvent,
+  Track,
   ConnectionState as LivekitConnectionState,
 } from "livekit-client";
 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 { logger, type Logger } from "matrix-js-sdk/lib/logger";
 import { type LivekitTransportConfig } from "matrix-js-sdk/lib/matrixrtc";
 
 import {
@@ -509,6 +512,79 @@ describe("remote participants", () => {
   });
 });
 
+describe("remote track logging", () => {
+  it("logs remote participant and track events on the connection logger", () => {
+    setupTest();
+    const info = vi.fn();
+    const testLogger = {
+      getChild: (): unknown => testLogger,
+      info,
+      debug: vi.fn(),
+      warn: vi.fn(),
+      error: vi.fn(),
+    } as unknown as Logger;
+    new Connection(
+      {
+        client,
+        roomId: ROOM_ID,
+        transport: livekitFocus,
+        scope: testScope,
+        ownMembershipIdentity: ownMemberMock,
+        livekitRoomFactory: () => fakeLivekitRoom,
+      },
+      testLogger,
+    );
+    info.mockClear(); // drop the constructor log line
+
+    const bob = mockRemoteParticipant({
+      identity: "@bob:example.org:DEV111",
+      sid: "PA_bob",
+    });
+    const pub = {
+      kind: "audio",
+      source: "microphone",
+      trackSid: "TR_mic",
+      isMuted: false,
+    } as unknown as RemoteTrackPublication;
+    const messages = (): string[] => info.mock.calls.map((c) => c[0] as string);
+
+    fakeLivekitRoom.emit(RoomEvent.ParticipantConnected, bob);
+    fakeLivekitRoom.emit(
+      RoomEvent.TrackSubscribed,
+      {} as RemoteTrack,
+      pub,
+      bob,
+    );
+    fakeLivekitRoom.emit(RoomEvent.TrackMuted, pub, bob);
+    fakeLivekitRoom.emit(
+      RoomEvent.TrackStreamStateChanged,
+      pub,
+      Track.StreamState.Paused,
+      bob,
+    );
+    expect(messages()).toEqual([
+      "Participant connected: @bob:example.org:DEV111 (PA_bob)",
+      "Subscribed: audio microphone TR_mic of @bob:example.org:DEV111 muted=false",
+      "Muted: audio microphone TR_mic of @bob:example.org:DEV111",
+      "Stream paused: audio microphone TR_mic of @bob:example.org:DEV111",
+    ]);
+
+    // Local mute events are already logged by the Publisher
+    fakeLivekitRoom.emit(RoomEvent.TrackMuted, pub, {
+      ...fakeLocalParticipant,
+      isLocal: true,
+    } as unknown as LocalParticipant);
+    expect(messages().filter((m) => m.startsWith("Muted"))).toHaveLength(1);
+
+    // Listeners are removed when the scope ends
+    testScope.end();
+    fakeLivekitRoom.emit(RoomEvent.ParticipantDisconnected, bob);
+    expect(
+      messages().filter((m) => m.startsWith("Participant disconnected")),
+    ).toHaveLength(0);
+  });
+});
+
 //
 // NOT USED ANYMORE ?
 //

src/state/CallViewModel/remoteMembers/Connection.ts

@@ -13,8 +13,14 @@ import {
 import {
   ConnectionError,
   ConnectionErrorReason,
+  type Participant,
   type RemoteParticipant,
+  type RemoteTrackPublication,
   type Room as LivekitRoom,
+  RoomEvent,
+  type SubscriptionError,
+  type Track,
+  type TrackPublication,
 } from "livekit-client";
 import { type LivekitTransportConfig } from "matrix-js-sdk/lib/matrixrtc";
 import { BehaviorSubject, map } from "rxjs";
@@ -164,6 +170,7 @@ export class Connection {
       // Only tracks remote participants
       connectedParticipantsObserver(this.livekitRoom),
     );
+    this.logRemoteTrackEvents();
 
     scope.onEnd(() => {
       this.logger.info(`Connection scope ended, stopping connection`);
@@ -171,6 +178,87 @@ export class Connection {
     });
   }
 
+  /**
+   * Logs the lifecycle of remote participants and their tracks as seen by
+   * livekit-client, so that rageshakes show what a tile should have been
+   * rendering (published, subscribed, muted, paused) for each remote member.
+   */
+  private logRemoteTrackEvents(): void {
+    const room = this.livekitRoom;
+    const log = this.logger.getChild("[RemoteTracks]");
+    const track = (pub: TrackPublication, p: Participant): string =>
+      `${pub.kind} ${pub.source} ${pub.trackSid} of ${p.identity}`;
+
+    const onParticipantConnected = (p: RemoteParticipant): void =>
+      log.info(`Participant connected: ${p.identity} (${p.sid})`);
+    const onParticipantDisconnected = (p: RemoteParticipant): void =>
+      log.info(`Participant disconnected: ${p.identity} (${p.sid})`);
+    const onTrackPublished = (
+      pub: RemoteTrackPublication,
+      p: RemoteParticipant,
+    ): void => log.info(`Published: ${track(pub, p)} muted=${pub.isMuted}`);
+    const onTrackUnpublished = (
+      pub: RemoteTrackPublication,
+      p: RemoteParticipant,
+    ): void => log.info(`Unpublished: ${track(pub, p)}`);
+    const onTrackSubscribed = (
+      _t: Track,
+      pub: RemoteTrackPublication,
+      p: RemoteParticipant,
+    ): void => log.info(`Subscribed: ${track(pub, p)} muted=${pub.isMuted}`);
+    const onTrackUnsubscribed = (
+      _t: Track,
+      pub: RemoteTrackPublication,
+      p: RemoteParticipant,
+    ): void => log.info(`Unsubscribed: ${track(pub, p)}`);
+    const onTrackSubscriptionFailed = (
+      trackSid: string,
+      p: RemoteParticipant,
+      reason?: SubscriptionError,
+    ): void =>
+      log.warn(
+        `Subscription failed: ${trackSid} of ${p.identity} reason=${reason}`,
+      );
+    // Mute events also fire for the local participant, which the Publisher
+    // already logs.
+    const onTrackMuted = (pub: TrackPublication, p: Participant): void => {
+      if (!p.isLocal) log.info(`Muted: ${track(pub, p)}`);
+    };
+    const onTrackUnmuted = (pub: TrackPublication, p: Participant): void => {
+      if (!p.isLocal) log.info(`Unmuted: ${track(pub, p)}`);
+    };
+    const onTrackStreamStateChanged = (
+      pub: RemoteTrackPublication,
+      state: Track.StreamState,
+      p: RemoteParticipant,
+    ): void => log.info(`Stream ${state}: ${track(pub, p)}`);
+
+    room
+      .on(RoomEvent.ParticipantConnected, onParticipantConnected)
+      .on(RoomEvent.ParticipantDisconnected, onParticipantDisconnected)
+      .on(RoomEvent.TrackPublished, onTrackPublished)
+      .on(RoomEvent.TrackUnpublished, onTrackUnpublished)
+      .on(RoomEvent.TrackSubscribed, onTrackSubscribed)
+      .on(RoomEvent.TrackUnsubscribed, onTrackUnsubscribed)
+      .on(RoomEvent.TrackSubscriptionFailed, onTrackSubscriptionFailed)
+      .on(RoomEvent.TrackMuted, onTrackMuted)
+      .on(RoomEvent.TrackUnmuted, onTrackUnmuted)
+      .on(RoomEvent.TrackStreamStateChanged, onTrackStreamStateChanged);
+    this.scope.onEnd(() => {
+      room
+        .off(RoomEvent.ParticipantConnected, onParticipantConnected)
+        .off(RoomEvent.ParticipantDisconnected, onParticipantDisconnected)
+        .off(RoomEvent.TrackPublished, onTrackPublished)
+        .off(RoomEvent.TrackUnpublished, onTrackUnpublished)
+        .off(RoomEvent.TrackSubscribed, onTrackSubscribed)
+        .off(RoomEvent.TrackUnsubscribed, onTrackUnsubscribed)
+        .off(RoomEvent.TrackSubscriptionFailed, onTrackSubscriptionFailed)
+        .off(RoomEvent.TrackMuted, onTrackMuted)
+        .off(RoomEvent.TrackUnmuted, onTrackUnmuted)
+        .off(RoomEvent.TrackStreamStateChanged, onTrackStreamStateChanged);
+    });
+  }
+
   /**
    * Starts the connection.
    *