Skip to content

Commit 3cec377

Browse files
toger5toger5
committed
Consistent RTC logging
1 parent 3f03c1d commit 3cec377

8 files changed

+122
-108
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

+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.

‎src/matrixrtc/MatrixRTCSession.ts

+20-15
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,13 +365,17 @@ 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, () =>
@@ -381,14 +385,14 @@ export class MatrixRTCSession extends TypedEventEmitter<MatrixRTCSessionEvent, M
381385
// Create Encryption manager
382386
let transport;
383387
if (joinConfig?.useExperimentalToDeviceTransport) {
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 {
394398
transport = new RoomKeyTransport(this.roomSubset, this.client, this.statistics);
@@ -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)