Make logging consistent for matrixRTC

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,17 +18,27 @@ 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;
     let room: Room & {
         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,42 +253,42 @@ 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];
 
         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.