Make logging consistent for matrixRTC (#4788)

* Consistent RTC logging

* tests: Add more RTC key transport tests

* test: improve rtc key room transport test

* fixup: missing mock

* rtc: more tests

* coverage trick

---------

Co-authored-by: Valere <bill.carson@valrsoft.com>

spec/unit/matrixrtc/MatrixRTCSession.spec.ts

@@ -993,6 +993,7 @@ describe("MatrixRTCSession", () => {
 
                     sess!.joinRoomSession([mockFocus], mockFocus, {
                         manageMediaKeys: true,
+                        useNewMembershipManager: true,
                         useExperimentalToDeviceTransport: true,
                     });
 

spec/unit/matrixrtc/MembershipManager.spec.ts

@@ -31,6 +31,7 @@ import { LegacyMembershipManager } from "../../../src/matrixrtc/LegacyMembership
 import { makeMockClient, makeMockRoom, membershipTemplate, mockCallMembership, type MockClient } from "./mocks";
 import { MembershipManager } from "../../../src/matrixrtc/NewMembershipManager";
 import { defer } from "../../../src/utils";
+import { logger } from "../../../src/logger.ts";
 
 function waitForMockCall(method: MockedFunction<any>, returnVal?: Promise<any>) {
     return new Promise<void>((resolve) => {
@@ -763,3 +764,19 @@ describe.each([
         });
     });
 });
+
+it("Should prefix log with MembershipManager used", () => {
+    const client = makeMockClient("@alice:example.org", "AAAAAAA");
+    const room = makeMockRoom(membershipTemplate);
+
+    const membershipManager = new MembershipManager(undefined, room, client, () => undefined, logger);
+
+    const spy = jest.spyOn(console, "error");
+    // Double join
+    membershipManager.join([]);
+    membershipManager.join([]);
+
+    expect(spy).toHaveBeenCalled();
+    const logline: string = spy.mock.calls[0][0];
+    expect(logline.startsWith("[NewMembershipManager]")).toBe(true);
+});

spec/unit/matrixrtc/RoomKeyTransport.spec.ts

@@ -18,7 +18,9 @@ import { makeMockEvent, makeMockRoom, membershipTemplate, makeKey } from "./mock
 import { RoomKeyTransport } from "../../../src/matrixrtc/RoomKeyTransport";
 import { KeyTransportEvents } from "../../../src/matrixrtc/IKeyTransport";
 import { EventType, MatrixClient, RoomEvent } from "../../../src";
-import type { IRoomTimelineData, MatrixEvent, Room } from "../../../src";
+import { type IRoomTimelineData, MatrixEvent, type Room } from "../../../src";
+import type { Mocked } from "jest-mock";
+import type { Logger } from "../../../src/logger.ts";
 
 describe("RoomKeyTransport", () => {
     let client: MatrixClient;
@@ -26,9 +28,17 @@ describe("RoomKeyTransport", () => {
         emitTimelineEvent: (event: MatrixEvent) => void;
     };
     let transport: RoomKeyTransport;
+    let mockLogger: Mocked<Logger>;
+
     const onCallEncryptionMock = jest.fn();
     beforeEach(() => {
         onCallEncryptionMock.mockReset();
+        mockLogger = {
+            debug: jest.fn(),
+            warn: jest.fn(),
+            info: jest.fn(),
+        } as unknown as Mocked<Logger>;
+
         const statistics = {
             counters: {
                 roomEventEncryptionKeysSent: 0,
@@ -41,7 +51,9 @@ describe("RoomKeyTransport", () => {
         room = makeMockRoom([membershipTemplate]);
         client = new MatrixClient({ baseUrl: "base_url" });
         client.matrixRTC.start();
-        transport = new RoomKeyTransport(room, client, statistics);
+        transport = new RoomKeyTransport(room, client, statistics, {
+            getChild: jest.fn().mockReturnValue(mockLogger),
+        } as unknown as Mocked<Logger>);
         transport.on(KeyTransportEvents.ReceivedKeys, (...p) => {
             onCallEncryptionMock(...p);
         });
@@ -138,4 +150,78 @@ describe("RoomKeyTransport", () => {
             }
         });
     });
+
+    describe("malformed events", () => {
+        const MALFORMED_EVENT = [
+            // empty content
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                sender: "@alice:example.com",
+                content: {},
+            }),
+            // no sender
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                content: {
+                    call_id: "",
+                    keys: [makeKey(0, "testKey")],
+                    sent_ts: Date.now(),
+                    device_id: "AAAAAAA",
+                },
+            }),
+            // Call_id not empty string
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                sender: "@alice:example.com",
+                content: {
+                    call_id: "FOO",
+                    keys: [makeKey(0, "testKey")],
+                    sent_ts: Date.now(),
+                    device_id: "AAAAAAA",
+                },
+            }),
+            // Various Malformed keys
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                sender: "@alice:example.com",
+                content: {
+                    call_id: "",
+                    keys: "FOO",
+                    sent_ts: Date.now(),
+                    device_id: "AAAAAAA",
+                },
+            }),
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                sender: "@alice:example.com",
+                content: {
+                    call_id: "",
+                    keys: [{ index: 0 }],
+                    sent_ts: Date.now(),
+                    device_id: "AAAAAAA",
+                },
+            }),
+            new MatrixEvent({
+                type: EventType.CallEncryptionKeysPrefix,
+                sender: "@alice:example.com",
+                content: {
+                    call_id: "",
+                    keys: [
+                        {
+                            key: "BASE64KEY",
+                            index: "mcall",
+                        },
+                    ],
+                    sent_ts: Date.now(),
+                    device_id: "AAAAAAA",
+                },
+            }),
+        ];
+
+        test.each(MALFORMED_EVENT)("should warn on malformed event %j", (event) => {
+            transport.onEncryptionEvent(event);
+            expect(mockLogger.warn).toHaveBeenCalled();
+            expect(onCallEncryptionMock).toHaveBeenCalledTimes(0);
+        });
+    });
 });

spec/unit/matrixrtc/ToDeviceKeyTransport.spec.ts

@@ -205,31 +205,31 @@ describe("ToDeviceKeyTransport", () => {
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
             {
-                keys: { keys: "ABCDEF" },
+                keys: { key: "ABCDEF" },
                 member: { claimed_device_id: "MYDEVICE" },
                 room_id: "!room:id",
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
             {
-                keys: { keys: "ABCDEF", index: 2 },
+                keys: { key: "ABCDEF", index: 2 },
                 room_id: "!room:id",
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
             {
-                keys: { keys: "ABCDEF", index: 2 },
+                keys: { key: "ABCDEF", index: 2 },
                 member: {},
                 room_id: "!room:id",
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
             {
-                keys: { keys: "ABCDEF", index: 2 },
+                keys: { key: "ABCDEF", index: 2 },
                 member: { claimed_device_id: "MYDEVICE" },
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
             {
-                keys: { keys: "ABCDEF", index: 2 },
+                keys: { key: "ABCDEF", index: 2 },
                 member: { claimed_device_id: "MYDEVICE" },
-                room_id: "!room:id",
+                room_id: "!wrong_room",
                 session: { application: "m.call", call_id: "", scope: "m.room" },
             },
         ];

spec/unit/matrixrtc/memberManagerTestEnvironment.ts

@@ -29,7 +29,7 @@ It is very specific to the MembershipManager.spec.ts file and introduces the fol
 import { TestEnvironment } from "jest-environment-jsdom";
 
 import { logger as rootLogger } from "../../../src/logger";
-const logger = rootLogger.getChild("MatrixRTCSession");
+const logger = rootLogger.getChild("[MatrixRTCSession]");
 
 class MemberManagerTestEnvironment extends TestEnvironment {
     handleTestEvent(event: any) {

src/matrixrtc/EncryptionManager.ts

@@ -1,4 +1,4 @@
-import { logger as rootLogger } from "../logger.ts";
+import { type Logger, logger as rootLogger } from "../logger.ts";
 import { type EncryptionConfig } from "./MatrixRTCSession.ts";
 import { secureRandomBase64Url } from "../randomstring.ts";
 import { decodeBase64, encodeUnpaddedBase64 } from "../base64.ts";
@@ -7,8 +7,6 @@ import { type CallMembership } from "./CallMembership.ts";
 import { type KeyTransportEventListener, KeyTransportEvents, type IKeyTransport } from "./IKeyTransport.ts";
 import { isMyMembership, type Statistics } from "./types.ts";
 
-const logger = rootLogger.getChild("MatrixRTCSession");
-
 /**
  * This interface is for testing and for making it possible to interchange the encryption manager.
  * @internal
@@ -78,7 +76,7 @@ export class EncryptionManager implements IEncryptionManager {
 
     private latestGeneratedKeyIndex = -1;
     private joinConfig: EncryptionConfig | undefined;
-
+    private logger: Logger;
     public constructor(
         private userId: string,
         private deviceId: string,
@@ -90,7 +88,10 @@ export class EncryptionManager implements IEncryptionManager {
             encryptionKeyIndex: number,
             participantId: string,
         ) => void,
-    ) {}
+        parentLogger?: Logger,
+    ) {
+        this.logger = (parentLogger ?? rootLogger).getChild(`[EncryptionManager]`);
+    }
 
     public getEncryptionKeys(): Map<string, Array<{ key: Uint8Array; timestamp: number }>> {
         return this.encryptionKeys;
@@ -158,11 +159,11 @@ export class EncryptionManager implements IEncryptionManager {
                 if (this.makeNewKeyTimeout) {
                     // existing rotation in progress, so let it complete
                 } else {
-                    logger.debug(`Member(s) have left: queueing sender key rotation`);
+                    this.logger.debug(`Member(s) have left: queueing sender key rotation`);
                     this.makeNewKeyTimeout = setTimeout(this.onRotateKeyTimeout, this.makeKeyDelay);
                 }
             } else if (anyJoined) {
-                logger.debug(`New member(s) have joined: re-sending keys`);
+                this.logger.debug(`New member(s) have joined: re-sending keys`);
                 this.requestSendCurrentKey();
             } else if (oldFingerprints) {
                 // does it look like any of the members have updated their memberships?
@@ -174,7 +175,7 @@ export class EncryptionManager implements IEncryptionManager {
                     Array.from(oldFingerprints).some((x) => !newFingerprints.has(x)) ||
                     Array.from(newFingerprints).some((x) => !oldFingerprints.has(x));
                 if (candidateUpdates) {
-                    logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
+                    this.logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
                     this.requestSendCurrentKey();
                 }
             }
@@ -190,7 +191,7 @@ export class EncryptionManager implements IEncryptionManager {
     private makeNewSenderKey(delayBeforeUse = false): number {
         const encryptionKey = secureRandomBase64Url(16);
         const encryptionKeyIndex = this.getNewEncryptionKeyIndex();
-        logger.info("Generated new key at index " + encryptionKeyIndex);
+        this.logger.info("Generated new key at index " + encryptionKeyIndex);
         this.setEncryptionKey(
             this.userId,
             this.deviceId,
@@ -213,7 +214,7 @@ export class EncryptionManager implements IEncryptionManager {
             this.lastEncryptionKeyUpdateRequest &&
             this.lastEncryptionKeyUpdateRequest + this.updateEncryptionKeyThrottle > Date.now()
         ) {
-            logger.info("Last encryption key event sent too recently: postponing");
+            this.logger.info("Last encryption key event sent too recently: postponing");
             if (this.keysEventUpdateTimeout === undefined) {
                 this.keysEventUpdateTimeout = setTimeout(
                     () => void this.sendEncryptionKeysEvent(),
@@ -252,18 +253,18 @@ export class EncryptionManager implements IEncryptionManager {
         const myKeys = this.getKeysForParticipant(this.userId, this.deviceId);
 
         if (!myKeys) {
-            logger.warn("Tried to send encryption keys event but no keys found!");
+            this.logger.warn("Tried to send encryption keys event but no keys found!");
             return;
         }
 
         if (typeof indexToSend !== "number" && this.latestGeneratedKeyIndex === -1) {
-            logger.warn("Tried to send encryption keys event but no current key index found!");
+            this.logger.warn("Tried to send encryption keys event but no current key index found!");
             return;
         }
 
         const keyIndexToSend = indexToSend ?? this.latestGeneratedKeyIndex;
 
-        logger.info(
+        this.logger.info(
             `Try sending encryption keys event. keyIndexToSend=${keyIndexToSend} (method parameter: ${indexToSend})`,
         );
         const keyToSend = myKeys[keyIndexToSend];
@@ -271,23 +272,23 @@ export class EncryptionManager implements IEncryptionManager {
         try {
             this.statistics.counters.roomEventEncryptionKeysSent += 1;
             await this.transport.sendKey(encodeUnpaddedBase64(keyToSend), keyIndexToSend, this.getMemberships());
-            logger.debug(
+            this.logger.debug(
                 `sendEncryptionKeysEvent participantId=${this.userId}:${this.deviceId} numKeys=${myKeys.length} currentKeyIndex=${this.latestGeneratedKeyIndex} keyIndexToSend=${keyIndexToSend}`,
                 this.encryptionKeys,
             );
         } catch (error) {
             if (this.keysEventUpdateTimeout === undefined) {
                 const resendDelay = safeGetRetryAfterMs(error, 5000);
-                logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
+                this.logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
                 this.keysEventUpdateTimeout = setTimeout(() => void this.sendEncryptionKeysEvent(), resendDelay);
             } else {
-                logger.info("Not scheduling key resend as another re-send is already pending");
+                this.logger.info("Not scheduling key resend as another re-send is already pending");
             }
         }
     };
 
     public onNewKeyReceived: KeyTransportEventListener = (userId, deviceId, keyBase64Encoded, index, timestamp) => {
-        logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
+        this.logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
         this.setEncryptionKey(userId, deviceId, index, keyBase64Encoded, timestamp);
     };
 
@@ -330,7 +331,7 @@ export class EncryptionManager implements IEncryptionManager {
         timestamp: number,
         delayBeforeUse = false,
     ): void {
-        logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
+        this.logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
         const keyBin = decodeBase64(encryptionKeyString);
 
         const participantId = getParticipantId(userId, deviceId);
@@ -343,7 +344,7 @@ export class EncryptionManager implements IEncryptionManager {
 
         if (existingKeyAtIndex) {
             if (existingKeyAtIndex.timestamp > timestamp) {
-                logger.info(
+                this.logger.info(
                     `Ignoring new key at index ${encryptionKeyIndex} for ${participantId} as it is older than existing known key`,
                 );
                 return;
@@ -372,7 +373,7 @@ export class EncryptionManager implements IEncryptionManager {
         if (delayBeforeUse) {
             const useKeyTimeout = setTimeout(() => {
                 this.setNewKeyTimeouts.delete(useKeyTimeout);
-                logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
+                this.logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
 
                 this.onEncryptionKeysChanged(keyBin, encryptionKeyIndex, participantId);
             }, this.useKeyDelay);
@@ -386,7 +387,7 @@ export class EncryptionManager implements IEncryptionManager {
         if (!this.manageMediaKeys) return;
 
         this.makeNewKeyTimeout = undefined;
-        logger.info("Making new sender key for key rotation");
+        this.logger.info("Making new sender key for key rotation");
         const newKeyIndex = this.makeNewSenderKey(true);
         // send immediately: if we're about to start sending with a new key, it's
         // important we get it out to others as soon as we can.

src/matrixrtc/MatrixRTCSession.ts

@@ -14,7 +14,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
-import { logger as rootLogger } from "../logger.ts";
+import { type Logger, logger as rootLogger } from "../logger.ts";
 import { TypedEventEmitter } from "../models/typed-event-emitter.ts";
 import { EventTimeline } from "../models/event-timeline.ts";
 import { type Room } from "../models/room.ts";
@@ -33,8 +33,6 @@ import { type Statistics } from "./types.ts";
 import { RoomKeyTransport } from "./RoomKeyTransport.ts";
 import type { IMembershipManager } from "./IMembershipManager.ts";
 
-const logger = rootLogger.getChild("MatrixRTCSession");
-
 export enum MatrixRTCSessionEvent {
     // A member joined, left, or updated a property of their membership.
     MembershipsChanged = "memberships_changed",
@@ -169,7 +167,7 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
     private encryptionManager?: IEncryptionManager;
     // The session Id of the call, this is the call_id of the call Member event.
     private _callId: string | undefined;
-
+    private logger: Logger;
     /**
      * This timeout is responsible to track any expiration. We need to know when we have to start
      * to ignore other call members. There is no callback for this. This timeout will always be configured to
@@ -206,6 +204,7 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
     public static callMembershipsForRoom(
         room: Pick<Room, "getLiveTimeline" | "roomId" | "hasMembershipState">,
     ): CallMembership[] {
+        const logger = rootLogger.getChild(`[MatrixRTCSession ${room.roomId}]`);
         const roomState = room.getLiveTimeline().getState(EventTimeline.FORWARDS);
         if (!roomState) {
             logger.warn("Couldn't get state for room " + room.roomId);
@@ -321,6 +320,7 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
         public memberships: CallMembership[],
     ) {
         super();
+        this.logger = rootLogger.getChild(`[MatrixRTCSession ${roomSubset.roomId}]`);
         this._callId = memberships[0]?.callId;
         const roomState = this.roomSubset.getLiveTimeline().getState(EventTimeline.FORWARDS);
         // TODO: double check if this is actually needed. Should be covered by refreshRoom in MatrixRTCSessionManager
@@ -365,13 +365,17 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
      */
     public joinRoomSession(fociPreferred: Focus[], fociActive?: Focus, joinConfig?: JoinSessionConfig): void {
         if (this.isJoined()) {
-            logger.info(`Already joined to session in room ${this.roomSubset.roomId}: ignoring join call`);
+            this.logger.info(`Already joined to session in room ${this.roomSubset.roomId}: ignoring join call`);
             return;
         } else {
-            // Create MembershipManager
+            // Create MembershipManager and pass the RTCSession logger (with room id info)
             if (joinConfig?.useNewMembershipManager ?? false) {
-                this.membershipManager = new MembershipManager(joinConfig, this.roomSubset, this.client, () =>
-                    this.getOldestMembership(),
+                this.membershipManager = new MembershipManager(
+                    joinConfig,
+                    this.roomSubset,
+                    this.client,
+                    () => this.getOldestMembership(),
+                    this.logger,
                 );
             } else {
                 this.membershipManager = new LegacyMembershipManager(joinConfig, this.roomSubset, this.client, () =>
@@ -381,14 +385,14 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
             // Create Encryption manager
             let transport;
             if (joinConfig?.useExperimentalToDeviceTransport) {
-                logger.info("Using experimental to-device transport for encryption keys");
+                this.logger.info("Using experimental to-device transport for encryption keys");
                 transport = new ToDeviceKeyTransport(
                     this.client.getUserId()!,
                     this.client.getDeviceId()!,
                     this.roomSubset.roomId,
                     this.client,
                     this.statistics,
-                    logger,
+                    this.logger,
                 );
             } else {
                 transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics);
@@ -402,12 +406,13 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
                 (keyBin: Uint8Array<ArrayBufferLike>, encryptionKeyIndex: number, participantId: string) => {
                     this.emit(MatrixRTCSessionEvent.EncryptionKeyChanged, keyBin, encryptionKeyIndex, participantId);
                 },
+                this.logger,
             );
         }
 
         // Join!
         this.membershipManager!.join(fociPreferred, fociActive, (e) => {
-            logger.error("MembershipManager encountered an unrecoverable error: ", e);
+            this.logger.error("MembershipManager encountered an unrecoverable error: ", e);
             this.emit(MatrixRTCSessionEvent.MembershipManagerError, e);
             this.emit(MatrixRTCSessionEvent.JoinStateChanged, this.isJoined());
         });
@@ -428,11 +433,11 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
      */
     public async leaveRoomSession(timeout: number | undefined = undefined): Promise<boolean> {
         if (!this.isJoined()) {
-            logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`);
+            this.logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`);
             return false;
         }
 
-        logger.info(`Leaving call session in room ${this.roomSubset.roomId}`);
+        this.logger.info(`Leaving call session in room ${this.roomSubset.roomId}`);
 
         this.encryptionManager!.leave();
 
@@ -553,8 +558,8 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
             oldMemberships.some((m, i) => !CallMembership.equal(m, this.memberships[i]));
 
         if (changed) {
-            logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`);
-            logDurationSync(logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => {
+            this.logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`);
+            logDurationSync(this.logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => {
                 this.emit(MatrixRTCSessionEvent.MembershipsChanged, oldMemberships, this.memberships);
             });
 

src/matrixrtc/MatrixRTCSessionManager.ts

@@ -23,7 +23,7 @@ import { type MatrixEvent } from "../models/event.ts";
 import { MatrixRTCSession } from "./MatrixRTCSession.ts";
 import { EventType } from "../@types/event.ts";
 
-const logger = rootLogger.getChild("MatrixRTCSessionManager");
+const logger = rootLogger.getChild("[MatrixRTCSessionManager]");
 
 export enum MatrixRTCSessionManagerEvents {
     // A member has joined the MatrixRTC session, creating an active session in a room where there wasn't previously

src/matrixrtc/NewMembershipManager.ts

@@ -19,7 +19,7 @@ import { UpdateDelayedEventAction } from "../@types/requests.ts";
 import { type MatrixClient } from "../client.ts";
 import { UnsupportedDelayedEventsEndpointError } from "../errors.ts";
 import { ConnectionError, HTTPError, MatrixError } from "../http-api/errors.ts";
-import { logger as rootLogger } from "../logger.ts";
+import { type Logger, logger as rootLogger } from "../logger.ts";
 import { type Room } from "../models/room.ts";
 import { defer, type IDeferred } from "../utils.ts";
 import { type CallMembership, DEFAULT_EXPIRE_DURATION, type SessionMembershipData } from "./CallMembership.ts";
@@ -35,8 +35,6 @@ import {
     type MembershipManagerEventHandlerMap,
 } from "./IMembershipManager.ts";
 
-const logger = rootLogger.getChild("MatrixRTCSession");
-
 /* MembershipActionTypes:
                            
 On Join:  ───────────────┐   ┌───────────────(1)───────────┐
@@ -146,6 +144,8 @@ export class MembershipManager
     implements IMembershipManager
 {
     private activated = false;
+    private logger: Logger;
+
     public isActivated(): boolean {
         return this.activated;
     }
@@ -164,7 +164,7 @@ export class MembershipManager
      */
     public join(fociPreferred: Focus[], focusActive?: Focus, onError?: (error: unknown) => void): void {
         if (this.scheduler.running) {
-            logger.error("MembershipManager is already running. Ignoring join request.");
+            this.logger.error("MembershipManager is already running. Ignoring join request.");
             return;
         }
         this.fociPreferred = fociPreferred;
@@ -177,7 +177,7 @@ export class MembershipManager
         this.scheduler
             .startWithJoin()
             .catch((e) => {
-                logger.error("MembershipManager stopped because: ", e);
+                this.logger.error("MembershipManager stopped because: ", e);
                 onError?.(e);
             })
             .finally(() => {
@@ -201,7 +201,7 @@ export class MembershipManager
      */
     public leave(timeout?: number): Promise<boolean> {
         if (!this.scheduler.running) {
-            logger.warn("Called MembershipManager.leave() even though the MembershipManager is not running");
+            this.logger.warn("Called MembershipManager.leave() even though the MembershipManager is not running");
             return Promise.resolve(true);
         }
 
@@ -228,9 +228,9 @@ export class MembershipManager
                 MembershipActionType.SendDelayedEvent,
                 MembershipActionType.SendJoinEvent,
             ];
-            logger.warn("Missing own membership: force re-join");
+            this.logger.warn("Missing own membership: force re-join");
             if (this.scheduler.actions.find((a) => sendingMembershipActions.includes(a.type as MembershipActionType))) {
-                logger.error(
+                this.logger.error(
                     "NewMembershipManger tried adding another `SendFirstDelayedEvent` actions even though we already have one in the Queue\nActionQueueOnMemberUpdate:",
                     this.scheduler.actions,
                 );
@@ -252,7 +252,7 @@ export class MembershipManager
                     return oldestMembership?.getPreferredFoci()[0];
                 }
             } else {
-                logger.warn("Unknown own ActiveFocus type. This makes it impossible to connect to an SFU.");
+                this.logger.warn("Unknown own ActiveFocus type. This makes it impossible to connect to an SFU.");
             }
         } else {
             // We do not understand the membership format (could be legacy). We default to oldestMembership
@@ -281,16 +281,38 @@ export class MembershipManager
             | "_unstable_updateDelayedEvent"
         >,
         private getOldestMembership: () => CallMembership | undefined,
+        parentLogger?: Logger,
     ) {
         super();
+        this.logger = (parentLogger ?? rootLogger).getChild(`[NewMembershipManager]`);
         const [userId, deviceId] = [this.client.getUserId(), this.client.getDeviceId()];
         if (userId === null) throw Error("Missing userId in client");
         if (deviceId === null) throw Error("Missing deviceId in client");
         this.deviceId = deviceId;
         this.stateKey = this.makeMembershipStateKey(userId, deviceId);
         this.state = MembershipManager.defaultState;
+        this.scheduler = new ActionScheduler((type): Promise<ActionUpdate> => {
+            if (this.oldStatus) {
+                // we put this at the beginning of the actions scheduler loop handle callback since it is a loop this
+                // is equivalent to running it at the end of the loop. (just after applying the status/action list changes)
+                // This order is required because this method needs to return the action updates.
+                this.logger.debug(
+                    `MembershipManager applied action changes. Status: ${this.oldStatus} -> ${this.status}`,
+                );
+                if (this.oldStatus !== this.status) {
+                    this.emit(MembershipManagerEvent.StatusChanged, this.oldStatus, this.status);
+                }
+            }
+            this.oldStatus = this.status;
+            this.logger.debug(`MembershipManager before processing action. status=${this.oldStatus}`);
+            return this.membershipLoopHandler(type);
+        }, this.logger);
     }
 
+    // scheduler
+    private oldStatus?: Status;
+    private scheduler: ActionScheduler;
+
     // MembershipManager mutable state.
     private state: MembershipManagerState;
     private static get defaultState(): MembershipManagerState {
@@ -346,23 +368,6 @@ export class MembershipManager
         return this.joinConfig?.maximumNetworkErrorRetryCount ?? 10;
     }
 
-    // Scheduler:
-    private oldStatus?: Status;
-    private scheduler = new ActionScheduler((type): Promise<ActionUpdate> => {
-        if (this.oldStatus) {
-            // we put this at the beginning of the actions scheduler loop handle callback since it is a loop this
-            // is equivalent to running it at the end of the loop. (just after applying the status/action list changes)
-            // This order is required because this method needs to return the action updates.
-            logger.debug(`MembershipManager applied action changes. Status: ${this.oldStatus} -> ${this.status}`);
-            if (this.oldStatus !== this.status) {
-                this.emit(MembershipManagerEvent.StatusChanged, this.oldStatus, this.status);
-            }
-        }
-        this.oldStatus = this.status;
-        logger.debug(`MembershipManager before processing action. status=${this.oldStatus}`);
-        return this.membershipLoopHandler(type);
-    });
-
     // LOOP HANDLER:
     private async membershipLoopHandler(type: MembershipActionType): Promise<ActionUpdate> {
         switch (type) {
@@ -468,9 +473,9 @@ export class MembershipManager
                     // This action was scheduled because we are in the process of joining
                     // log and fall through
                     if (this.isUnsupportedDelayedEndpoint(e)) {
-                        logger.info("Not using delayed event because the endpoint is not supported");
+                        this.logger.info("Not using delayed event because the endpoint is not supported");
                     } else {
-                        logger.info("Not using delayed event because: " + e);
+                        this.logger.info("Not using delayed event because: " + e);
                     }
                     // On any other error we fall back to not using delayed events and send the join state event immediately
                     return createInsertActionUpdate(MembershipActionType.SendJoinEvent);
@@ -561,7 +566,7 @@ export class MembershipManager
                 if (update) return update;
 
                 // On any other error we fall back to SendLeaveEvent (this includes hard errors from rate limiting)
-                logger.warn(
+                this.logger.warn(
                     "Encountered unexpected error during SendScheduledDelayedLeaveEvent. Falling back to SendLeaveEvent",
                     e,
                 );
@@ -695,7 +700,7 @@ export class MembershipManager
             if (typeof maxDelayAllowed === "number" && this.membershipServerSideExpiryTimeout > maxDelayAllowed) {
                 this.membershipServerSideExpiryTimeoutOverride = maxDelayAllowed;
             }
-            logger.warn("Retry sending delayed disconnection event due to server timeout limitations:", error);
+            this.logger.warn("Retry sending delayed disconnection event due to server timeout limitations:", error);
             return true;
         }
         return false;
@@ -737,9 +742,9 @@ export class MembershipManager
             const defaultMs = 5000;
             try {
                 resendDelay = error.getRetryAfterMs() ?? defaultMs;
-                logger.info(`Rate limited by server, retrying in ${resendDelay}ms`);
+                this.logger.info(`Rate limited by server, retrying in ${resendDelay}ms`);
             } catch (e) {
-                logger.warn(
+                this.logger.warn(
                     `Error while retrieving a rate-limit retry delay, retrying after default delay of ${defaultMs}`,
                     e,
                 );
@@ -767,7 +772,7 @@ export class MembershipManager
         const retryDurationString = this.callMemberEventRetryDelayMinimum / 1000 + "s";
         const retryCounterString = "(" + retries + "/" + this.maximumNetworkErrorRetryCount + ")";
         if (error instanceof Error && error.name === "AbortError") {
-            logger.warn(
+            this.logger.warn(
                 "Network local timeout error while sending event, retrying in " +
                     retryDurationString +
                     " " +
@@ -785,12 +790,12 @@ export class MembershipManager
             //
             // A proper fix would be to either find a place to convert the `HttpError` into a `MatrixError` and the `processError`
             // method to handle it as expected or to adjust `processError` to also process `HttpError`'s.
-            logger.warn(
+            this.logger.warn(
                 "delayed event update timeout error, retrying in " + retryDurationString + " " + retryCounterString,
                 error,
             );
         } else if (error instanceof ConnectionError) {
-            logger.warn(
+            this.logger.warn(
                 "Network connection error while sending event, retrying in " +
                     retryDurationString +
                     " " +
@@ -803,7 +808,7 @@ export class MembershipManager
             error.httpStatus >= 500 &&
             error.httpStatus < 600
         ) {
-            logger.warn(
+            this.logger.warn(
                 "Server error while sending event, retrying in " + retryDurationString + " " + retryCounterString,
                 error,
             );
@@ -879,7 +884,7 @@ export class MembershipManager
             return Status.Disconnected;
         }
 
-        logger.error("MembershipManager has an unknown state. Actions: ", actions);
+        this.logger.error("MembershipManager has an unknown state. Actions: ", actions);
         return Status.Unknown;
     }
 }

src/matrixrtc/NewMembershipManagerActionScheduler.ts

@@ -1,10 +1,8 @@
-import { logger as rootLogger } from "../logger.ts";
+import { type Logger, logger as rootLogger } from "../logger.ts";
 import { type EmptyObject } from "../matrix.ts";
 import { sleep } from "../utils.ts";
 import { MembershipActionType } from "./NewMembershipManager.ts";
 
-const logger = rootLogger.getChild("MatrixRTCSession");
-
 /** @internal */
 export interface Action {
     /**
@@ -40,6 +38,7 @@ export type ActionUpdate =
  * @internal
  */
 export class ActionScheduler {
+    private logger: Logger;
     /**
      * This is tracking the state of the scheduler loop.
      * Only used to prevent starting the loop twice.
@@ -49,11 +48,14 @@ export class ActionScheduler {
     public constructor(
         /** This is the callback called for each scheduled action (`this.addAction()`) */
         private membershipLoopHandler: (type: MembershipActionType) => Promise<ActionUpdate>,
-    ) {}
+        parentLogger?: Logger,
+    ) {
+        this.logger = (parentLogger ?? rootLogger).getChild(`[NewMembershipActionScheduler]`);
+    }
 
     // function for the wakeup mechanism (in case we add an action externally and need to leave the current sleep)
     private wakeup: (update: ActionUpdate) => void = (update: ActionUpdate): void => {
-        logger.error("Cannot call wakeup before calling `startWithJoin()`");
+        this.logger.error("Cannot call wakeup before calling `startWithJoin()`");
     };
     private _actions: Action[] = [];
     public get actions(): Action[] {
@@ -69,7 +71,7 @@ export class ActionScheduler {
      */
     public async startWithJoin(): Promise<void> {
         if (this.running) {
-            logger.error("Cannot call startWithJoin() on NewMembershipActionScheduler while already running");
+            this.logger.error("Cannot call startWithJoin() on NewMembershipActionScheduler while already running");
             return;
         }
         this.running = true;
@@ -92,7 +94,7 @@ export class ActionScheduler {
 
                 let handlerResult: ActionUpdate = {};
                 if (!wakeupUpdate) {
-                    logger.debug(
+                    this.logger.debug(
                         `Current MembershipManager processing: ${nextAction.type}\nQueue:`,
                         this._actions,
                         `\nDate.now: "${Date.now()}`,
@@ -121,7 +123,7 @@ export class ActionScheduler {
             this.running = false;
         }
 
-        logger.debug("Leave MembershipManager ActionScheduler loop (no more actions)");
+        this.logger.debug("Leave MembershipManager ActionScheduler loop (no more actions)");
     }
 
     public initiateJoin(): void {

src/matrixrtc/RoomKeyTransport.ts

@@ -18,7 +18,7 @@ import type { MatrixClient } from "../client.ts";
 import type { EncryptionKeysEventContent, Statistics } from "./types.ts";
 import { EventType } from "../@types/event.ts";
 import { type MatrixError } from "../http-api/errors.ts";
-import { logger, type Logger } from "../logger.ts";
+import { logger as rootLogger, type Logger } from "../logger.ts";
 import { KeyTransportEvents, type KeyTransportEventsHandlerMap, type IKeyTransport } from "./IKeyTransport.ts";
 import { type MatrixEvent } from "../models/event.ts";
 import { type CallMembership } from "./CallMembership.ts";
@@ -29,7 +29,7 @@ export class RoomKeyTransport
     extends TypedEventEmitter<KeyTransportEvents, KeyTransportEventsHandlerMap>
     implements IKeyTransport
 {
-    private readonly prefixedLogger: Logger;
+    private readonly logger: Logger;
 
     public constructor(
         private room: Pick<Room, "on" | "off" | "roomId">,
@@ -38,9 +38,10 @@ export class RoomKeyTransport
             "sendEvent" | "getDeviceId" | "getUserId" | "cancelPendingEvent" | "decryptEventIfNeeded"
         >,
         private statistics: Statistics,
+        parentLogger?: Logger,
     ) {
         super();
-        this.prefixedLogger = logger.getChild(`[RTC: ${room.roomId} RoomKeyTransport]`);
+        this.logger = (parentLogger ?? rootLogger).getChild(`[RoomKeyTransport]`);
     }
     public start(): void {
         this.room.on(RoomEvent.Timeline, (ev) => void this.consumeCallEncryptionEvent(ev));
@@ -54,23 +55,23 @@ export class RoomKeyTransport
 
         if (event.isDecryptionFailure()) {
             if (!isRetry) {
-                logger.warn(
+                this.logger.warn(
                     `Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason} will retry once only`,
                 );
                 // retry after 1 second. After this we give up.
                 setTimeout(() => void this.consumeCallEncryptionEvent(event, true), 1000);
             } else {
-                logger.warn(`Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason}`);
+                this.logger.warn(`Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason}`);
             }
             return;
         } else if (isRetry) {
-            logger.info(`Decryption succeeded for event ${event.getId()} after retry`);
+            this.logger.info(`Decryption succeeded for event ${event.getId()} after retry`);
         }
 
         if (event.getType() !== EventType.CallEncryptionKeysPrefix) return Promise.resolve();
 
         if (!this.room) {
-            logger.error(`Got room state event for unknown room ${event.getRoomId()}!`);
+            this.logger.error(`Got room state event for unknown room ${event.getRoomId()}!`);
             return Promise.resolve();
         }
 
@@ -95,7 +96,7 @@ export class RoomKeyTransport
         try {
             await this.client.sendEvent(this.room.roomId, EventType.CallEncryptionKeysPrefix, content);
         } catch (error) {
-            this.prefixedLogger.error("Failed to send call encryption keys", error);
+            this.logger.error("Failed to send call encryption keys", error);
             const matrixError = error as MatrixError;
             if (matrixError.event) {
                 // cancel the pending event: we'll just generate a new one with our latest
@@ -114,20 +115,20 @@ export class RoomKeyTransport
         const callId = content["call_id"];
 
         if (!userId) {
-            logger.warn(`Received m.call.encryption_keys with no userId: callId=${callId}`);
+            this.logger.warn(`Received m.call.encryption_keys with no userId: callId=${callId}`);
             return;
         }
 
         // We currently only handle callId = "" (which is the default for room scoped calls)
         if (callId !== "") {
-            logger.warn(
+            this.logger.warn(
                 `Received m.call.encryption_keys with unsupported callId: userId=${userId}, deviceId=${deviceId}, callId=${callId}`,
             );
             return;
         }
 
         if (!Array.isArray(content.keys)) {
-            logger.warn(`Received m.call.encryption_keys where keys wasn't an array: callId=${callId}`);
+            this.logger.warn(`Received m.call.encryption_keys where keys wasn't an array: callId=${callId}`);
             return;
         }
 
@@ -135,7 +136,7 @@ export class RoomKeyTransport
             // We store our own sender key in the same set along with keys from others, so it's
             // important we don't allow our own keys to be set by one of these events (apart from
             // the fact that we don't need it anyway because we already know our own keys).
-            logger.info("Ignoring our own keys event");
+            this.logger.info("Ignoring our own keys event");
             return;
         }
 
@@ -145,7 +146,7 @@ export class RoomKeyTransport
 
         for (const key of content.keys) {
             if (!key) {
-                logger.info("Ignoring false-y key in keys event");
+                this.logger.info("Ignoring false-y key in keys event");
                 continue;
             }
 
@@ -163,11 +164,11 @@ export class RoomKeyTransport
                 typeof encryptionKey !== "string" ||
                 typeof encryptionKeyIndex !== "number"
             ) {
-                logger.warn(
+                this.logger.warn(
                     `Malformed call encryption_key: userId=${userId}, deviceId=${deviceId}, encryptionKeyIndex=${encryptionKeyIndex} callId=${callId}`,
                 );
             } else {
-                logger.debug(
+                this.logger.debug(
                     `onCallEncryption userId=${userId}:${deviceId} encryptionKeyIndex=${encryptionKeyIndex} age=${age}ms`,
                 );
                 this.emit(

src/matrixrtc/ToDeviceKeyTransport.ts

@@ -16,7 +16,7 @@ limitations under the License.
 
 import { TypedEventEmitter } from "../models/typed-event-emitter.ts";
 import { type IKeyTransport, KeyTransportEvents, type KeyTransportEventsHandlerMap } from "./IKeyTransport.ts";
-import { type Logger } from "../logger.ts";
+import { type Logger, logger as rootLogger } from "../logger.ts";
 import type { CallMembership } from "./CallMembership.ts";
 import type { EncryptionKeysToDeviceEventContent, Statistics } from "./types.ts";
 import { ClientEvent, type MatrixClient } from "../client.ts";
@@ -31,7 +31,7 @@ export class ToDeviceKeyTransport
     extends TypedEventEmitter<KeyTransportEvents, KeyTransportEventsHandlerMap>
     implements IKeyTransport
 {
-    private readonly prefixedLogger: Logger;
+    private readonly logger: Logger;
 
     public constructor(
         private userId: string,
@@ -39,10 +39,10 @@ export class ToDeviceKeyTransport
         private roomId: string,
         private client: Pick<MatrixClient, "encryptAndSendToDevice" | "on" | "off">,
         private statistics: Statistics,
-        logger: Logger,
+        parentLogger?: Logger,
     ) {
         super();
-        this.prefixedLogger = logger.getChild(`[${roomId} ToDeviceKeyTransport]`);
+        this.logger = (parentLogger ?? rootLogger).getChild(`[ToDeviceKeyTransport]`);
     }
 
     public start(): void {
@@ -74,7 +74,7 @@ export class ToDeviceKeyTransport
             .filter((member) => {
                 // filter malformed call members
                 if (member.sender == undefined || member.deviceId == undefined) {
-                    this.prefixedLogger.warn(`Malformed call member: ${member.sender}|${member.deviceId}`);
+                    this.logger.warn(`Malformed call member: ${member.sender}|${member.deviceId}`);
                     return false;
                 }
                 // Filter out me
@@ -91,7 +91,7 @@ export class ToDeviceKeyTransport
             await this.client.encryptAndSendToDevice(EventType.CallEncryptionKeysPrefix, targets, content);
             this.statistics.counters.roomEventEncryptionKeysSent += 1;
         } else {
-            this.prefixedLogger.warn("No targets found for sending key");
+            this.logger.warn("No targets found for sending key");
         }
     }
 
@@ -145,21 +145,21 @@ export class ToDeviceKeyTransport
         const roomId = content.room_id;
         if (!roomId) {
             // Invalid event
-            this.prefixedLogger.warn("Malformed Event: invalid call encryption keys event, no roomId");
+            this.logger.warn("Malformed Event: invalid call encryption keys event, no roomId");
             return;
         }
         if (roomId !== this.roomId) {
-            this.prefixedLogger.warn("Malformed Event: Mismatch roomId");
+            this.logger.warn("Malformed Event: Mismatch roomId");
             return;
         }
 
         if (!content.keys || !content.keys.key || typeof content.keys.index !== "number") {
-            this.prefixedLogger.warn("Malformed Event: Missing keys field");
+            this.logger.warn("Malformed Event: Missing keys field");
             return;
         }
 
         if (!content.member || !content.member.claimed_device_id) {
-            this.prefixedLogger.warn("Malformed Event: Missing claimed_device_id");
+            this.logger.warn("Malformed Event: Missing claimed_device_id");
             return;
         }