Skip to content

Commit 40f3cee

Browse files
toger5toger5
committed
consistent matrix RTC logging
1 parent 5c01a2d commit 40f3cee

8 files changed

+125
-111
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

+23-22
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
@@ -86,7 +84,7 @@ export class EncryptionManager implements IEncryptionManager {
8684
private mediaTrailerKeyIndexInUse = -1;
8785
private latestGeneratedKeyIndex = -1;
8886
private joinConfig: EncryptionConfig | undefined;
89-
87+
private logger: Logger;
9088
public constructor(
9189
private userId: string,
9290
private deviceId: string,
@@ -98,7 +96,10 @@ export class EncryptionManager implements IEncryptionManager {
9896
encryptionKeyIndex: number,
9997
participantId: string,
10098
) => void,
101-
) {}
99+
parentLogger?: Logger,
100+
) {
101+
this.logger = (parentLogger ?? rootLogger).getChild(`[EncryptionManager]`);
102+
}
102103

103104
public getEncryptionKeys(): Map<string, Array<{ key: Uint8Array; timestamp: number }>> {
104105
return this.encryptionKeys;
@@ -166,11 +167,11 @@ export class EncryptionManager implements IEncryptionManager {
166167
if (this.makeNewKeyTimeout) {
167168
// existing rotation in progress, so let it complete
168169
} else {
169-
logger.debug(`Member(s) have left: queueing sender key rotation`);
170+
this.logger.debug(`Member(s) have left: queueing sender key rotation`);
170171
this.makeNewKeyTimeout = setTimeout(this.onRotateKeyTimeout, this.makeKeyDelay);
171172
}
172173
} else if (anyJoined) {
173-
logger.debug(`New member(s) have joined: re-sending keys`);
174+
this.logger.debug(`New member(s) have joined: re-sending keys`);
174175
this.requestSendCurrentKey();
175176
} else if (oldFingerprints) {
176177
// does it look like any of the members have updated their memberships?
@@ -182,7 +183,7 @@ export class EncryptionManager implements IEncryptionManager {
182183
Array.from(oldFingerprints).some((x) => !newFingerprints.has(x)) ||
183184
Array.from(newFingerprints).some((x) => !oldFingerprints.has(x));
184185
if (candidateUpdates) {
185-
logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
186+
this.logger.debug(`Member(s) have updated/reconnected: re-sending keys to everyone`);
186187
this.requestSendCurrentKey();
187188
}
188189
}
@@ -198,7 +199,7 @@ export class EncryptionManager implements IEncryptionManager {
198199
private makeNewSenderKey(delayBeforeUse = false): number {
199200
const encryptionKey = secureRandomBase64Url(16);
200201
const encryptionKeyIndex = this.getNewEncryptionKeyIndex();
201-
logger.info("Generated new key at index " + encryptionKeyIndex);
202+
this.logger.info("Generated new key at index " + encryptionKeyIndex);
202203
this.setEncryptionKey(
203204
this.userId,
204205
this.deviceId,
@@ -221,7 +222,7 @@ export class EncryptionManager implements IEncryptionManager {
221222
this.lastEncryptionKeyUpdateRequest &&
222223
this.lastEncryptionKeyUpdateRequest + this.updateEncryptionKeyThrottle > Date.now()
223224
) {
224-
logger.info("Last encryption key event sent too recently: postponing");
225+
this.logger.info("Last encryption key event sent too recently: postponing");
225226
if (this.keysEventUpdateTimeout === undefined) {
226227
this.keysEventUpdateTimeout = setTimeout(
227228
() => void this.sendEncryptionKeysEvent(),
@@ -260,47 +261,47 @@ export class EncryptionManager implements IEncryptionManager {
260261
const myKeys = this.getKeysForParticipant(this.userId, this.deviceId);
261262

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

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

272273
const keyIndexToSend = indexToSend ?? this.latestGeneratedKeyIndex;
273274
// TODO remove this debug log. it just shows then when sending mediaTrailerKeyIndexInUse contained the wrong index.
274-
logger.debug(
275+
this.logger.debug(
275276
`Compare key in use to last generated key\n`,
276277
`latestGeneratedKeyIndex: ${this.latestGeneratedKeyIndex}\n`,
277278
`mediaTrailerKeyIndexInUse: ${this.mediaTrailerKeyIndexInUse}`,
278279
);
279-
logger.info(
280+
this.logger.info(
280281
`Try sending encryption keys event. keyIndexToSend=${keyIndexToSend} (method parameter: ${indexToSend})`,
281282
);
282283
const keyToSend = myKeys[keyIndexToSend];
283284

284285
try {
285286
this.statistics.counters.roomEventEncryptionKeysSent += 1;
286287
await this.transport.sendKey(encodeUnpaddedBase64(keyToSend), keyIndexToSend, this.getMemberships());
287-
logger.debug(
288+
this.logger.debug(
288289
`sendEncryptionKeysEvent participantId=${this.userId}:${this.deviceId} numKeys=${myKeys.length} currentKeyIndex=${this.latestGeneratedKeyIndex} keyIndexToSend=${keyIndexToSend}`,
289290
this.encryptionKeys,
290291
);
291292
} catch (error) {
292293
if (this.keysEventUpdateTimeout === undefined) {
293294
const resendDelay = safeGetRetryAfterMs(error, 5000);
294-
logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
295+
this.logger.warn(`Failed to send m.call.encryption_key, retrying in ${resendDelay}`, error);
295296
this.keysEventUpdateTimeout = setTimeout(() => void this.sendEncryptionKeysEvent(), resendDelay);
296297
} else {
297-
logger.info("Not scheduling key resend as another re-send is already pending");
298+
this.logger.info("Not scheduling key resend as another re-send is already pending");
298299
}
299300
}
300301
};
301302

302303
public onNewKeyReceived: KeyTransportEventListener = (userId, deviceId, keyBase64Encoded, index, timestamp) => {
303-
logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
304+
this.logger.debug(`Received key over key transport ${userId}:${deviceId} at index ${index}`);
304305
this.setEncryptionKey(userId, deviceId, index, keyBase64Encoded, timestamp);
305306
};
306307

@@ -343,7 +344,7 @@ export class EncryptionManager implements IEncryptionManager {
343344
timestamp: number,
344345
delayBeforeUse = false,
345346
): void {
346-
logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
347+
this.logger.debug(`Setting encryption key for ${userId}:${deviceId} at index ${encryptionKeyIndex}`);
347348
const keyBin = decodeBase64(encryptionKeyString);
348349

349350
const participantId = getParticipantId(userId, deviceId);
@@ -356,7 +357,7 @@ export class EncryptionManager implements IEncryptionManager {
356357

357358
if (existingKeyAtIndex) {
358359
if (existingKeyAtIndex.timestamp > timestamp) {
359-
logger.info(
360+
this.logger.info(
360361
`Ignoring new key at index ${encryptionKeyIndex} for ${participantId} as it is older than existing known key`,
361362
);
362363
return;
@@ -385,7 +386,7 @@ export class EncryptionManager implements IEncryptionManager {
385386
if (delayBeforeUse) {
386387
const useKeyTimeout = setTimeout(() => {
387388
this.setNewKeyTimeouts.delete(useKeyTimeout);
388-
logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
389+
this.logger.info(`Delayed-emitting key changed event for ${participantId} index ${encryptionKeyIndex}`);
389390
if (userId === this.userId && deviceId === this.deviceId) {
390391
this.mediaTrailerKeyIndexInUse = encryptionKeyIndex;
391392
}
@@ -404,7 +405,7 @@ export class EncryptionManager implements IEncryptionManager {
404405
if (!this.manageMediaKeys) return;
405406

406407
this.makeNewKeyTimeout = undefined;
407-
logger.info("Making new sender key for key rotation");
408+
this.logger.info("Making new sender key for key rotation");
408409
const newKeyIndex = this.makeNewSenderKey(true);
409410
// send immediately: if we're about to start sending with a new key, it's
410411
// important we get it out to others as soon as we can.

‎src/matrixrtc/MatrixRTCSession.ts

+22-17
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,33 +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,
391-
logger,
395+
this.logger,
392396
);
393397
} else {
394-
transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics);
398+
transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics, this.logger);
395399
}
396400
this.encryptionManager = new EncryptionManager(
397401
this.client.getUserId()!,
@@ -402,12 +406,13 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
402406
(keyBin: Uint8Array<ArrayBufferLike>, encryptionKeyIndex: number, participantId: string) => {
403407
this.emit(MatrixRTCSessionEvent.EncryptionKeyChanged, keyBin, encryptionKeyIndex, participantId);
404408
},
409+
this.logger,
405410
);
406411
}
407412

408413
// Join!
409414
this.membershipManager!.join(fociPreferred, fociActive, (e) => {
410-
logger.error("MembershipManager encountered an unrecoverable error: ", e);
415+
this.logger.error("MembershipManager encountered an unrecoverable error: ", e);
411416
this.emit(MatrixRTCSessionEvent.MembershipManagerError, e);
412417
this.emit(MatrixRTCSessionEvent.JoinStateChanged, this.isJoined());
413418
});
@@ -428,11 +433,11 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
428433
*/
429434
public async leaveRoomSession(timeout: number | undefined = undefined): Promise<boolean> {
430435
if (!this.isJoined()) {
431-
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`);
432437
return false;
433438
}
434439

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

437442
this.encryptionManager!.leave();
438443

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

555560
if (changed) {
556-
logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`);
557-
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", () => {
558563
this.emit(MatrixRTCSessionEvent.MembershipsChanged, oldMemberships, this.memberships);
559564
});
560565

‎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)