Skip to content

Commit ea55bff

Browse files
toger5toger5
committed
consistend matrix rtc logging
1 parent 499c56e commit ea55bff

8 files changed

+123
-107
lines changed

‎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

+21-20
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
@@ -83,7 +81,7 @@ export class EncryptionManager implements IEncryptionManager {
8381
private currentEncryptionKeyIndex = -1;
8482

8583
private joinConfig: EncryptionConfig | undefined;
86-
84+
private logger: Logger;
8785
public constructor(
8886
private userId: string,
8987
private deviceId: string,
@@ -95,7 +93,10 @@ export class EncryptionManager implements IEncryptionManager {
9593
encryptionKeyIndex: number,
9694
participantId: string,
9795
) => void,
98-
) {}
96+
parentLogger?: Logger,
97+
) {
98+
this.logger = (parentLogger ?? rootLogger).getChild(`[EncryptionManager]`);
99+
}
99100

100101
public getEncryptionKeys(): Map<string, Array<{ key: Uint8Array; timestamp: number }>> {
101102
return this.encryptionKeys;
@@ -163,11 +164,11 @@ export class EncryptionManager implements IEncryptionManager {
163164
if (this.makeNewKeyTimeout) {
164165
// existing rotation in progress, so let it complete
165166
} else {
166-
logger.debug(`Member(s) have left: queueing sender key rotation`);
167+
this.logger.debug(`Member(s) have left: queueing sender key rotation`);
167168
this.makeNewKeyTimeout = setTimeout(this.onRotateKeyTimeout, this.makeKeyDelay);
168169
}
169170
} else if (anyJoined) {
170-
logger.debug(`New member(s) have joined: re-sending keys`);
171+
this.logger.debug(`New member(s) have joined: re-sending keys`);
171172
this.requestSendCurrentKey();
172173
} else if (oldFingerprints) {
173174
// does it look like any of the members have updated their memberships?
@@ -179,7 +180,7 @@ export class EncryptionManager implements IEncryptionManager {
179180
Array.from(oldFingerprints).some((x) => !newFingerprints.has(x)) ||
180181
Array.from(newFingerprints).some((x) => !oldFingerprints.has(x));
181182
if (candidateUpdates) {
182-
logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
183+
this.logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
183184
this.requestSendCurrentKey();
184185
}
185186
}
@@ -195,7 +196,7 @@ export class EncryptionManager implements IEncryptionManager {
195196
private makeNewSenderKey(delayBeforeUse = false): number {
196197
const encryptionKey = secureRandomBase64Url(16);
197198
const encryptionKeyIndex = this.getNewEncryptionKeyIndex();
198-
logger.info("Generated new key at index " + encryptionKeyIndex);
199+
this.logger.info("Generated new key at index " + encryptionKeyIndex);
199200
this.setEncryptionKey(
200201
this.userId,
201202
this.deviceId,
@@ -218,7 +219,7 @@ export class EncryptionManager implements IEncryptionManager {
218219
this.lastEncryptionKeyUpdateRequest &&
219220
this.lastEncryptionKeyUpdateRequest + this.updateEncryptionKeyThrottle > Date.now()
220221
) {
221-
logger.info("Last encryption key event sent too recently: postponing");
222+
this.logger.info("Last encryption key event sent too recently: postponing");
222223
if (this.keysEventUpdateTimeout === undefined) {
223224
this.keysEventUpdateTimeout = setTimeout(
224225
() => void this.sendEncryptionKeysEvent(),
@@ -254,17 +255,17 @@ export class EncryptionManager implements IEncryptionManager {
254255

255256
if (!this.joined) return;
256257

257-
logger.info(`Sending encryption keys event. indexToSend=${indexToSend}`);
258+
this.logger.info(`Sending encryption keys event. indexToSend=${indexToSend}`);
258259

259260
const myKeys = this.getKeysForParticipant(this.userId, this.deviceId);
260261

261262
if (!myKeys) {
262-
logger.warn("Tried to send encryption keys event but no keys found!");
263+
this.logger.warn("Tried to send encryption keys event but no keys found!");
263264
return;
264265
}
265266

266267
if (typeof indexToSend !== "number" && this.currentEncryptionKeyIndex === -1) {
267-
logger.warn("Tried to send encryption keys event but no current key index found!");
268+
this.logger.warn("Tried to send encryption keys event but no current key index found!");
268269
return;
269270
}
270271

@@ -274,17 +275,17 @@ export class EncryptionManager implements IEncryptionManager {
274275
try {
275276
this.statistics.counters.roomEventEncryptionKeysSent += 1;
276277
await this.transport.sendKey(encodeUnpaddedBase64(keyToSend), keyIndexToSend, this.getMemberships());
277-
logger.debug(
278+
this.logger.debug(
278279
`Embedded-E2EE-LOG updateEncryptionKeyEvent participantId=${this.userId}:${this.deviceId} numKeys=${myKeys.length} currentKeyIndex=${this.currentEncryptionKeyIndex} keyIndexToSend=${keyIndexToSend}`,
279280
this.encryptionKeys,
280281
);
281282
} catch (error) {
282283
if (this.keysEventUpdateTimeout === undefined) {
283284
const resendDelay = safeGetRetryAfterMs(error, 5000);
284-
logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
285+
this.logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
285286
this.keysEventUpdateTimeout = setTimeout(() => void this.sendEncryptionKeysEvent(), resendDelay);
286287
} else {
287-
logger.info("Not scheduling key resend as another re-send is already pending");
288+
this.logger.info("Not scheduling key resend as another re-send is already pending");
288289
}
289290
}
290291
};
@@ -332,7 +333,7 @@ export class EncryptionManager implements IEncryptionManager {
332333
timestamp: number,
333334
delayBeforeUse = false,
334335
): void {
335-
logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
336+
this.logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
336337
const keyBin = decodeBase64(encryptionKeyString);
337338

338339
const participantId = getParticipantId(userId, deviceId);
@@ -345,7 +346,7 @@ export class EncryptionManager implements IEncryptionManager {
345346

346347
if (existingKeyAtIndex) {
347348
if (existingKeyAtIndex.timestamp > timestamp) {
348-
logger.info(
349+
this.logger.info(
349350
`Ignoring new key at index ${encryptionKeyIndex} for ${participantId} as it is older than existing known key`,
350351
);
351352
return;
@@ -365,7 +366,7 @@ export class EncryptionManager implements IEncryptionManager {
365366
if (delayBeforeUse) {
366367
const useKeyTimeout = setTimeout(() => {
367368
this.setNewKeyTimeouts.delete(useKeyTimeout);
368-
logger.info(`Delayed-emitting key changed event for ${participantId} idx ${encryptionKeyIndex}`);
369+
this.logger.info(`Delayed-emitting key changed event for ${participantId} idx ${encryptionKeyIndex}`);
369370
if (userId === this.userId && deviceId === this.deviceId) {
370371
this.currentEncryptionKeyIndex = encryptionKeyIndex;
371372
}
@@ -384,7 +385,7 @@ export class EncryptionManager implements IEncryptionManager {
384385
if (!this.manageMediaKeys) return;
385386

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

‎src/matrixrtc/MatrixRTCSession.ts

+22-16
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ See the License for the specific language governing permissions and
1414
limitations under the License.
1515
*/
1616

17-
import { logger as rootLogger } from "../logger.ts";
17+
import { type Logger, logger as rootLogger } from "../logger.ts";
1818
import { TypedEventEmitter } from "../models/typed-event-emitter.ts";
1919
import { EventTimeline } from "../models/event-timeline.ts";
2020
import { type Room } from "../models/room.ts";
@@ -33,8 +33,6 @@ import { type Statistics } from "./types.ts";
3333
import { RoomKeyTransport } from "./RoomKeyTransport.ts";
3434
import type { IMembershipManager } from "./IMembershipManager.ts";
3535

36-
const logger = rootLogger.getChild("MatrixRTCSession");
37-
3836
export enum MatrixRTCSessionEvent {
3937
// A member joined, left, or updated a property of their membership.
4038
MembershipsChanged = "memberships_changed",
@@ -169,7 +167,7 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
169167
private encryptionManager?: IEncryptionManager;
170168
// The session Id of the call, this is the call_id of the call Member event.
171169
private _callId: string | undefined;
172-
170+
private logger: Logger;
173171
/**
174172
* This timeout is responsible to track any expiration. We need to know when we have to start
175173
* 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
206204
public static callMembershipsForRoom(
207205
room: Pick<Room, "getLiveTimeline" | "roomId" | "hasMembershipState">,
208206
): CallMembership[] {
207+
const logger = rootLogger.getChild(`[MatrixRTCSession ${room.roomId}]`);
209208
const roomState = room.getLiveTimeline().getState(EventTimeline.FORWARDS);
210209
if (!roomState) {
211210
logger.warn("Couldn't get state for room " + room.roomId);
@@ -321,6 +320,7 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
321320
public memberships: CallMembership[],
322321
) {
323322
super();
323+
this.logger = rootLogger.getChild(`[MatrixRTCSession ${roomSubset.roomId}]`);
324324
this._callId = memberships[0]?.callId;
325325
const roomState = this.roomSubset.getLiveTimeline().getState(EventTimeline.FORWARDS);
326326
// TODO: double check if this is actually needed. Should be covered by refreshRoom in MatrixRTCSessionManager
@@ -365,32 +365,37 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
365365
*/
366366
public joinRoomSession(fociPreferred: Focus[], fociActive?: Focus, joinConfig?: JoinSessionConfig): void {
367367
if (this.isJoined()) {
368-
logger.info(`Already joined to session in room ${this.roomSubset.roomId}: ignoring join call`);
368+
this.logger.info(`Already joined to session in room ${this.roomSubset.roomId}: ignoring join call`);
369369
return;
370370
} else {
371-
// Create MembershipManager
371+
// Create MembershipManager and pass the RTCSession logger (with room id info)
372372
if (joinConfig?.useNewMembershipManager ?? false) {
373-
this.membershipManager = new MembershipManager(joinConfig, this.roomSubset, this.client, () =>
374-
this.getOldestMembership(),
373+
this.membershipManager = new MembershipManager(
374+
joinConfig,
375+
this.roomSubset,
376+
this.client,
377+
() => this.getOldestMembership(),
378+
this.logger,
375379
);
376380
} else {
377381
this.membershipManager = new LegacyMembershipManager(joinConfig, this.roomSubset, this.client, () =>
378382
this.getOldestMembership(),
379383
);
380384
}
381-
// Create Encryption manager
385+
// Create Encryption manager and pass the RTCSession logger (with room id info)
382386
let transport;
383387
if (joinConfig?.useExperimentalToDeviceTransport == true) {
384-
logger.info("Using experimental to-device transport for encryption keys");
388+
this.logger.info("Using experimental to-device transport for encryption keys");
385389
transport = new ToDeviceKeyTransport(
386390
this.client.getUserId()!,
387391
this.client.getDeviceId()!,
388392
this.roomSubset.roomId,
389393
this.client,
390394
this.statistics,
395+
this.logger,
391396
);
392397
} else {
393-
transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics);
398+
transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics, this.logger);
394399
}
395400
this.encryptionManager = new EncryptionManager(
396401
this.client.getUserId()!,
@@ -401,12 +406,13 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
401406
(keyBin: Uint8Array<ArrayBufferLike>, encryptionKeyIndex: number, participantId: string) => {
402407
this.emit(MatrixRTCSessionEvent.EncryptionKeyChanged, keyBin, encryptionKeyIndex, participantId);
403408
},
409+
this.logger,
404410
);
405411
}
406412

407413
// Join!
408414
this.membershipManager!.join(fociPreferred, fociActive, (e) => {
409-
logger.error("MembershipManager encountered an unrecoverable error: ", e);
415+
this.logger.error("MembershipManager encountered an unrecoverable error: ", e);
410416
this.emit(MatrixRTCSessionEvent.MembershipManagerError, e);
411417
this.emit(MatrixRTCSessionEvent.JoinStateChanged, this.isJoined());
412418
});
@@ -427,11 +433,11 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
427433
*/
428434
public async leaveRoomSession(timeout: number | undefined = undefined): Promise<boolean> {
429435
if (!this.isJoined()) {
430-
logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`);
436+
this.logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`);
431437
return false;
432438
}
433439

434-
logger.info(`Leaving call session in room ${this.roomSubset.roomId}`);
440+
this.logger.info(`Leaving call session in room ${this.roomSubset.roomId}`);
435441

436442
this.encryptionManager!.leave();
437443

@@ -552,8 +558,8 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
552558
oldMemberships.some((m, i) => !CallMembership.equal(m, this.memberships[i]));
553559

554560
if (changed) {
555-
logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`);
556-
logDurationSync(logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => {
561+
this.logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`);
562+
logDurationSync(this.logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => {
557563
this.emit(MatrixRTCSessionEvent.MembershipsChanged, oldMemberships, this.memberships);
558564
});
559565

‎src/matrixrtc/MatrixRTCSessionManager.ts

+1-1
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ import { type MatrixEvent } from "../models/event.ts";
2323
import { MatrixRTCSession } from "./MatrixRTCSession.ts";
2424
import { EventType } from "../@types/event.ts";
2525

26-
const logger = rootLogger.getChild("MatrixRTCSessionManager");
26+
const logger = rootLogger.getChild("[MatrixRTCSessionManager]");
2727

2828
export enum MatrixRTCSessionManagerEvents {
2929
// A member has joined the MatrixRTC session, creating an active session in a room where there wasn't previously

0 commit comments

Comments
 (0)