From f8f5caaa0990096b45ae39343ec9b525808ac7fe Mon Sep 17 00:00:00 2001 From: Matthew Hodgson Date: Thu, 3 Sep 2026 16:50:30 +0100 Subject: [PATCH] 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. --- .../remoteMembers/Connection.test.ts | 78 +++++++++++++++- .../CallViewModel/remoteMembers/Connection.ts | 88 +++++++++++++++++++ 2 files changed, 165 insertions(+), 1 deletion(-) diff --git a/src/state/CallViewModel/remoteMembers/Connection.test.ts b/src/state/CallViewModel/remoteMembers/Connection.test.ts index 723295853..9d098d445 100644 --- a/src/state/CallViewModel/remoteMembers/Connection.test.ts +++ b/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 ? // diff --git a/src/state/CallViewModel/remoteMembers/Connection.ts b/src/state/CallViewModel/remoteMembers/Connection.ts index f320e6303..9310c9b82 100644 --- a/src/state/CallViewModel/remoteMembers/Connection.ts +++ b/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. *