Skip to content

Commit e3a3a52

Browse files
toger5BillCarsonFr
toger5
and
BillCarsonFr
authored
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 <[email protected]>
1 parent 3f03c1d commit e3a3a52

12 files changed

+234
-116
lines changed

‎spec/unit/matrixrtc/MatrixRTCSession.spec.ts

+1
Original file line numberDiff line numberDiff line change
@@ -993,6 +993,7 @@ describe("MatrixRTCSession", () => {
993993

994994
sess!.joinRoomSession([mockFocus], mockFocus, {
995995
manageMediaKeys: true,
996+
useNewMembershipManager: true,
996997
useExperimentalToDeviceTransport: true,
997998
});
998999

‎spec/unit/matrixrtc/MembershipManager.spec.ts

+17
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ import { LegacyMembershipManager } from "../../../src/matrixrtc/LegacyMembership
3131
import { makeMockClient, makeMockRoom, membershipTemplate, mockCallMembership, type MockClient } from "./mocks";
3232
import { MembershipManager } from "../../../src/matrixrtc/NewMembershipManager";
3333
import { defer } from "../../../src/utils";
34+
import { logger } from "../../../src/logger.ts";
3435

3536
function waitForMockCall(method: MockedFunction<any>, returnVal?: Promise<any>) {
3637
return new Promise<void>((resolve) => {
@@ -763,3 +764,19 @@ describe.each([
763764
});
764765
});
765766
});
767+
768+
it("Should prefix log with MembershipManager used", () => {
769+
const client = makeMockClient("@alice:example.org", "AAAAAAA");
770+
const room = makeMockRoom(membershipTemplate);
771+
772+
const membershipManager = new MembershipManager(undefined, room, client, () => undefined, logger);
773+
774+
const spy = jest.spyOn(console, "error");
775+
// Double join
776+
membershipManager.join([]);
777+
membershipManager.join([]);
778+
779+
expect(spy).toHaveBeenCalled();
780+
const logline: string = spy.mock.calls[0][0];
781+
expect(logline.startsWith("[NewMembershipManager]")).toBe(true);
782+
});

‎spec/unit/matrixrtc/RoomKeyTransport.spec.ts

+88-2
Original file line numberDiff line numberDiff line change
@@ -18,17 +18,27 @@ import { makeMockEvent, makeMockRoom, membershipTemplate, makeKey } from "./mock
1818
import { RoomKeyTransport } from "../../../src/matrixrtc/RoomKeyTransport";
1919
import { KeyTransportEvents } from "../../../src/matrixrtc/IKeyTransport";
2020
import { EventType, MatrixClient, RoomEvent } from "../../../src";
21-
import type { IRoomTimelineData, MatrixEvent, Room } from "../../../src";
21+
import { type IRoomTimelineData, MatrixEvent, type Room } from "../../../src";
22+
import type { Mocked } from "jest-mock";
23+
import type { Logger } from "../../../src/logger.ts";
2224

2325
describe("RoomKeyTransport", () => {
2426
let client: MatrixClient;
2527
let room: Room & {
2628
emitTimelineEvent: (event: MatrixEvent) => void;
2729
};
2830
let transport: RoomKeyTransport;
31+
let mockLogger: Mocked<Logger>;
32+
2933
const onCallEncryptionMock = jest.fn();
3034
beforeEach(() => {
3135
onCallEncryptionMock.mockReset();
36+
mockLogger = {
37+
debug: jest.fn(),
38+
warn: jest.fn(),
39+
info: jest.fn(),
40+
} as unknown as Mocked<Logger>;
41+
3242
const statistics = {
3343
counters: {
3444
roomEventEncryptionKeysSent: 0,
@@ -41,7 +51,9 @@ describe("RoomKeyTransport", () => {
4151
room = makeMockRoom([membershipTemplate]);
4252
client = new MatrixClient({ baseUrl: "base_url" });
4353
client.matrixRTC.start();
44-
transport = new RoomKeyTransport(room, client, statistics);
54+
transport = new RoomKeyTransport(room, client, statistics, {
55+
getChild: jest.fn().mockReturnValue(mockLogger),
56+
} as unknown as Mocked<Logger>);
4557
transport.on(KeyTransportEvents.ReceivedKeys, (...p) => {
4658
onCallEncryptionMock(...p);
4759
});
@@ -138,4 +150,78 @@ describe("RoomKeyTransport", () => {
138150
}
139151
});
140152
});
153+
154+
describe("malformed events", () => {
155+
const MALFORMED_EVENT = [
156+
// empty content
157+
new MatrixEvent({
158+
type: EventType.CallEncryptionKeysPrefix,
159+
sender: "@alice:example.com",
160+
content: {},
161+
}),
162+
// no sender
163+
new MatrixEvent({
164+
type: EventType.CallEncryptionKeysPrefix,
165+
content: {
166+
call_id: "",
167+
keys: [makeKey(0, "testKey")],
168+
sent_ts: Date.now(),
169+
device_id: "AAAAAAA",
170+
},
171+
}),
172+
// Call_id not empty string
173+
new MatrixEvent({
174+
type: EventType.CallEncryptionKeysPrefix,
175+
sender: "@alice:example.com",
176+
content: {
177+
call_id: "FOO",
178+
keys: [makeKey(0, "testKey")],
179+
sent_ts: Date.now(),
180+
device_id: "AAAAAAA",
181+
},
182+
}),
183+
// Various Malformed keys
184+
new MatrixEvent({
185+
type: EventType.CallEncryptionKeysPrefix,
186+
sender: "@alice:example.com",
187+
content: {
188+
call_id: "",
189+
keys: "FOO",
190+
sent_ts: Date.now(),
191+
device_id: "AAAAAAA",
192+
},
193+
}),
194+
new MatrixEvent({
195+
type: EventType.CallEncryptionKeysPrefix,
196+
sender: "@alice:example.com",
197+
content: {
198+
call_id: "",
199+
keys: [{ index: 0 }],
200+
sent_ts: Date.now(),
201+
device_id: "AAAAAAA",
202+
},
203+
}),
204+
new MatrixEvent({
205+
type: EventType.CallEncryptionKeysPrefix,
206+
sender: "@alice:example.com",
207+
content: {
208+
call_id: "",
209+
keys: [
210+
{
211+
key: "BASE64KEY",
212+
index: "mcall",
213+
},
214+
],
215+
sent_ts: Date.now(),
216+
device_id: "AAAAAAA",
217+
},
218+
}),
219+
];
220+
221+
test.each(MALFORMED_EVENT)("should warn on malformed event %j", (event) => {
222+
transport.onEncryptionEvent(event);
223+
expect(mockLogger.warn).toHaveBeenCalled();
224+
expect(onCallEncryptionMock).toHaveBeenCalledTimes(0);
225+
});
226+
});
141227
});

‎spec/unit/matrixrtc/ToDeviceKeyTransport.spec.ts

+6-6
Original file line numberDiff line numberDiff line change
@@ -205,31 +205,31 @@ describe("ToDeviceKeyTransport", () => {
205205
session: { application: "m.call", call_id: "", scope: "m.room" },
206206
},
207207
{
208-
keys: { keys: "ABCDEF" },
208+
keys: { key: "ABCDEF" },
209209
member: { claimed_device_id: "MYDEVICE" },
210210
room_id: "!room:id",
211211
session: { application: "m.call", call_id: "", scope: "m.room" },
212212
},
213213
{
214-
keys: { keys: "ABCDEF", index: 2 },
214+
keys: { key: "ABCDEF", index: 2 },
215215
room_id: "!room:id",
216216
session: { application: "m.call", call_id: "", scope: "m.room" },
217217
},
218218
{
219-
keys: { keys: "ABCDEF", index: 2 },
219+
keys: { key: "ABCDEF", index: 2 },
220220
member: {},
221221
room_id: "!room:id",
222222
session: { application: "m.call", call_id: "", scope: "m.room" },
223223
},
224224
{
225-
keys: { keys: "ABCDEF", index: 2 },
225+
keys: { key: "ABCDEF", index: 2 },
226226
member: { claimed_device_id: "MYDEVICE" },
227227
session: { application: "m.call", call_id: "", scope: "m.room" },
228228
},
229229
{
230-
keys: { keys: "ABCDEF", index: 2 },
230+
keys: { key: "ABCDEF", index: 2 },
231231
member: { claimed_device_id: "MYDEVICE" },
232-
room_id: "!room:id",
232+
room_id: "!wrong_room",
233233
session: { application: "m.call", call_id: "", scope: "m.room" },
234234
},
235235
];

‎spec/unit/matrixrtc/memberManagerTestEnvironment.ts

+1-1
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ It is very specific to the MembershipManager.spec.ts file and introduces the fol
2929
import { TestEnvironment } from "jest-environment-jsdom";
3030

3131
import { logger as rootLogger } from "../../../src/logger";
32-
const logger = rootLogger.getChild("MatrixRTCSession");
32+
const logger = rootLogger.getChild("[MatrixRTCSession]");
3333

3434
class MemberManagerTestEnvironment extends TestEnvironment {
3535
handleTestEvent(event: any) {

‎src/matrixrtc/EncryptionManager.ts

+22-21
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
import { logger as rootLogger } from "../logger.ts";
1+
import { type Logger, logger as rootLogger } from "../logger.ts";
22
import { type EncryptionConfig } from "./MatrixRTCSession.ts";
33
import { secureRandomBase64Url } from "../randomstring.ts";
44
import { decodeBase64, encodeUnpaddedBase64 } from "../base64.ts";
@@ -7,8 +7,6 @@ import { type CallMembership } from "./CallMembership.ts";
77
import { type KeyTransportEventListener, KeyTransportEvents, type IKeyTransport } from "./IKeyTransport.ts";
88
import { isMyMembership, type Statistics } from "./types.ts";
99

10-
const logger = rootLogger.getChild("MatrixRTCSession");
11-
1210
/**
1311
* This interface is for testing and for making it possible to interchange the encryption manager.
1412
* @internal
@@ -78,7 +76,7 @@ export class EncryptionManager implements IEncryptionManager {
7876

7977
private latestGeneratedKeyIndex = -1;
8078
private joinConfig: EncryptionConfig | undefined;
81-
79+
private logger: Logger;
8280
public constructor(
8381
private userId: string,
8482
private deviceId: string,
@@ -90,7 +88,10 @@ export class EncryptionManager implements IEncryptionManager {
9088
encryptionKeyIndex: number,
9189
participantId: string,
9290
) => void,
93-
) {}
91+
parentLogger?: Logger,
92+
) {
93+
this.logger = (parentLogger ?? rootLogger).getChild(`[EncryptionManager]`);
94+
}
9495

9596
public getEncryptionKeys(): Map<string, Array<{ key: Uint8Array; timestamp: number }>> {
9697
return this.encryptionKeys;
@@ -158,11 +159,11 @@ export class EncryptionManager implements IEncryptionManager {
158159
if (this.makeNewKeyTimeout) {
159160
// existing rotation in progress, so let it complete
160161
} else {
161-
logger.debug(`Member(s) have left: queueing sender key rotation`);
162+
this.logger.debug(`Member(s) have left: queueing sender key rotation`);
162163
this.makeNewKeyTimeout = setTimeout(this.onRotateKeyTimeout, this.makeKeyDelay);
163164
}
164165
} else if (anyJoined) {
165-
logger.debug(`New member(s) have joined: re-sending keys`);
166+
this.logger.debug(`New member(s) have joined: re-sending keys`);
166167
this.requestSendCurrentKey();
167168
} else if (oldFingerprints) {
168169
// does it look like any of the members have updated their memberships?
@@ -174,7 +175,7 @@ export class EncryptionManager implements IEncryptionManager {
174175
Array.from(oldFingerprints).some((x) => !newFingerprints.has(x)) ||
175176
Array.from(newFingerprints).some((x) => !oldFingerprints.has(x));
176177
if (candidateUpdates) {
177-
logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
178+
this.logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
178179
this.requestSendCurrentKey();
179180
}
180181
}
@@ -190,7 +191,7 @@ export class EncryptionManager implements IEncryptionManager {
190191
private makeNewSenderKey(delayBeforeUse = false): number {
191192
const encryptionKey = secureRandomBase64Url(16);
192193
const encryptionKeyIndex = this.getNewEncryptionKeyIndex();
193-
logger.info("Generated new key at index " + encryptionKeyIndex);
194+
this.logger.info("Generated new key at index " + encryptionKeyIndex);
194195
this.setEncryptionKey(
195196
this.userId,
196197
this.deviceId,
@@ -213,7 +214,7 @@ export class EncryptionManager implements IEncryptionManager {
213214
this.lastEncryptionKeyUpdateRequest &&
214215
this.lastEncryptionKeyUpdateRequest + this.updateEncryptionKeyThrottle > Date.now()
215216
) {
216-
logger.info("Last encryption key event sent too recently: postponing");
217+
this.logger.info("Last encryption key event sent too recently: postponing");
217218
if (this.keysEventUpdateTimeout === undefined) {
218219
this.keysEventUpdateTimeout = setTimeout(
219220
() => void this.sendEncryptionKeysEvent(),
@@ -252,42 +253,42 @@ export class EncryptionManager implements IEncryptionManager {
252253
const myKeys = this.getKeysForParticipant(this.userId, this.deviceId);
253254

254255
if (!myKeys) {
255-
logger.warn("Tried to send encryption keys event but no keys found!");
256+
this.logger.warn("Tried to send encryption keys event but no keys found!");
256257
return;
257258
}
258259

259260
if (typeof indexToSend !== "number" && this.latestGeneratedKeyIndex === -1) {
260-
logger.warn("Tried to send encryption keys event but no current key index found!");
261+
this.logger.warn("Tried to send encryption keys event but no current key index found!");
261262
return;
262263
}
263264

264265
const keyIndexToSend = indexToSend ?? this.latestGeneratedKeyIndex;
265266

266-
logger.info(
267+
this.logger.info(
267268
`Try sending encryption keys event. keyIndexToSend=${keyIndexToSend} (method parameter: ${indexToSend})`,
268269
);
269270
const keyToSend = myKeys[keyIndexToSend];
270271

271272
try {
272273
this.statistics.counters.roomEventEncryptionKeysSent += 1;
273274
await this.transport.sendKey(encodeUnpaddedBase64(keyToSend), keyIndexToSend, this.getMemberships());
274-
logger.debug(
275+
this.logger.debug(
275276
`sendEncryptionKeysEvent participantId=${this.userId}:${this.deviceId} numKeys=${myKeys.length} currentKeyIndex=${this.latestGeneratedKeyIndex} keyIndexToSend=${keyIndexToSend}`,
276277
this.encryptionKeys,
277278
);
278279
} catch (error) {
279280
if (this.keysEventUpdateTimeout === undefined) {
280281
const resendDelay = safeGetRetryAfterMs(error, 5000);
281-
logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
282+
this.logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
282283
this.keysEventUpdateTimeout = setTimeout(() => void this.sendEncryptionKeysEvent(), resendDelay);
283284
} else {
284-
logger.info("Not scheduling key resend as another re-send is already pending");
285+
this.logger.info("Not scheduling key resend as another re-send is already pending");
285286
}
286287
}
287288
};
288289

289290
public onNewKeyReceived: KeyTransportEventListener = (userId, deviceId, keyBase64Encoded, index, timestamp) => {
290-
logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
291+
this.logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
291292
this.setEncryptionKey(userId, deviceId, index, keyBase64Encoded, timestamp);
292293
};
293294

@@ -330,7 +331,7 @@ export class EncryptionManager implements IEncryptionManager {
330331
timestamp: number,
331332
delayBeforeUse = false,
332333
): void {
333-
logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
334+
this.logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
334335
const keyBin = decodeBase64(encryptionKeyString);
335336

336337
const participantId = getParticipantId(userId, deviceId);
@@ -343,7 +344,7 @@ export class EncryptionManager implements IEncryptionManager {
343344

344345
if (existingKeyAtIndex) {
345346
if (existingKeyAtIndex.timestamp > timestamp) {
346-
logger.info(
347+
this.logger.info(
347348
`Ignoring new key at index ${encryptionKeyIndex} for ${participantId} as it is older than existing known key`,
348349
);
349350
return;
@@ -372,7 +373,7 @@ export class EncryptionManager implements IEncryptionManager {
372373
if (delayBeforeUse) {
373374
const useKeyTimeout = setTimeout(() => {
374375
this.setNewKeyTimeouts.delete(useKeyTimeout);
375-
logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
376+
this.logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
376377

377378
this.onEncryptionKeysChanged(keyBin, encryptionKeyIndex, participantId);
378379
}, this.useKeyDelay);
@@ -386,7 +387,7 @@ export class EncryptionManager implements IEncryptionManager {
386387
if (!this.manageMediaKeys) return;
387388

388389
this.makeNewKeyTimeout = undefined;
389-
logger.info("Making new sender key for key rotation");
390+
this.logger.info("Making new sender key for key rotation");
390391
const newKeyIndex = this.makeNewSenderKey(true);
391392
// send immediately: if we're about to start sending with a new key, it's
392393
// important we get it out to others as soon as we can.

0 commit comments

Comments
 (0)