From 3cec377449371f9c582ac0e53b135a901f5921b5 Mon Sep 17 00:00:00 2001 From: Timo Date: Thu, 10 Apr 2025 12:19:39 +0200 Subject: [PATCH 1/6] Consistent RTC logging --- .../matrixrtc/memberManagerTestEnvironment.ts | 2 +- src/matrixrtc/EncryptionManager.ts | 43 +++++----- src/matrixrtc/MatrixRTCSession.ts | 35 ++++---- src/matrixrtc/MatrixRTCSessionManager.ts | 2 +- src/matrixrtc/NewMembershipManager.ts | 79 ++++++++++--------- .../NewMembershipManagerActionScheduler.ts | 18 +++-- src/matrixrtc/RoomKeyTransport.ts | 31 ++++---- src/matrixrtc/ToDeviceKeyTransport.ts | 20 ++--- 8 files changed, 122 insertions(+), 108 deletions(-) diff --git a/spec/unit/matrixrtc/memberManagerTestEnvironment.ts b/spec/unit/matrixrtc/memberManagerTestEnvironment.ts index f6c6e18dd6d..65ca4204be6 100644 --- a/spec/unit/matrixrtc/memberManagerTestEnvironment.ts +++ b/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) { diff --git a/src/matrixrtc/EncryptionManager.ts b/src/matrixrtc/EncryptionManager.ts index 8495f9920ba..7de1f197268 100644 --- a/src/matrixrtc/EncryptionManager.ts +++ b/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> { 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,18 +253,18 @@ 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]; @@ -271,23 +272,23 @@ export class EncryptionManager implements IEncryptionManager { 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. diff --git a/src/matrixrtc/MatrixRTCSession.ts b/src/matrixrtc/MatrixRTCSession.ts index 35d1e2e4076..70be5962c6a 100644 --- a/src/matrixrtc/MatrixRTCSession.ts +++ b/src/matrixrtc/MatrixRTCSession.ts @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { logger as rootLogger } from "../logger.ts"; +import { type Logger, logger as rootLogger } from "../logger.ts"; import { TypedEventEmitter } from "../models/typed-event-emitter.ts"; import { EventTimeline } from "../models/event-timeline.ts"; import { type Room } from "../models/room.ts"; @@ -33,8 +33,6 @@ import { type Statistics } from "./types.ts"; import { RoomKeyTransport } from "./RoomKeyTransport.ts"; import type { IMembershipManager } from "./IMembershipManager.ts"; -const logger = rootLogger.getChild("MatrixRTCSession"); - export enum MatrixRTCSessionEvent { // A member joined, left, or updated a property of their membership. MembershipsChanged = "memberships_changed", @@ -169,7 +167,7 @@ export class MatrixRTCSession extends TypedEventEmitter, ): CallMembership[] { + const logger = rootLogger.getChild(`[MatrixRTCSession ${room.roomId}]`); const roomState = room.getLiveTimeline().getState(EventTimeline.FORWARDS); if (!roomState) { logger.warn("Couldn't get state for room " + room.roomId); @@ -321,6 +320,7 @@ export class MatrixRTCSession extends TypedEventEmitter - this.getOldestMembership(), + this.membershipManager = new MembershipManager( + joinConfig, + this.roomSubset, + this.client, + () => this.getOldestMembership(), + this.logger, ); } else { this.membershipManager = new LegacyMembershipManager(joinConfig, this.roomSubset, this.client, () => @@ -381,14 +385,14 @@ export class MatrixRTCSession extends TypedEventEmitter, encryptionKeyIndex: number, participantId: string) => { this.emit(MatrixRTCSessionEvent.EncryptionKeyChanged, keyBin, encryptionKeyIndex, participantId); }, + this.logger, ); } // Join! this.membershipManager!.join(fociPreferred, fociActive, (e) => { - logger.error("MembershipManager encountered an unrecoverable error: ", e); + this.logger.error("MembershipManager encountered an unrecoverable error: ", e); this.emit(MatrixRTCSessionEvent.MembershipManagerError, e); this.emit(MatrixRTCSessionEvent.JoinStateChanged, this.isJoined()); }); @@ -428,11 +433,11 @@ export class MatrixRTCSession extends TypedEventEmitter { if (!this.isJoined()) { - logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`); + this.logger.info(`Not joined to session in room ${this.roomSubset.roomId}: ignoring leave call`); return false; } - logger.info(`Leaving call session in room ${this.roomSubset.roomId}`); + this.logger.info(`Leaving call session in room ${this.roomSubset.roomId}`); this.encryptionManager!.leave(); @@ -553,8 +558,8 @@ export class MatrixRTCSession extends TypedEventEmitter !CallMembership.equal(m, this.memberships[i])); if (changed) { - logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`); - logDurationSync(logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => { + this.logger.info(`Memberships for call in room ${this.roomSubset.roomId} have changed: emitting`); + logDurationSync(this.logger, "emit MatrixRTCSessionEvent.MembershipsChanged", () => { this.emit(MatrixRTCSessionEvent.MembershipsChanged, oldMemberships, this.memberships); }); diff --git a/src/matrixrtc/MatrixRTCSessionManager.ts b/src/matrixrtc/MatrixRTCSessionManager.ts index cc821934490..d3db4accea2 100644 --- a/src/matrixrtc/MatrixRTCSessionManager.ts +++ b/src/matrixrtc/MatrixRTCSessionManager.ts @@ -23,7 +23,7 @@ import { type MatrixEvent } from "../models/event.ts"; import { MatrixRTCSession } from "./MatrixRTCSession.ts"; import { EventType } from "../@types/event.ts"; -const logger = rootLogger.getChild("MatrixRTCSessionManager"); +const logger = rootLogger.getChild("[MatrixRTCSessionManager]"); export enum MatrixRTCSessionManagerEvents { // A member has joined the MatrixRTC session, creating an active session in a room where there wasn't previously diff --git a/src/matrixrtc/NewMembershipManager.ts b/src/matrixrtc/NewMembershipManager.ts index 10b47fe51ba..fad78e216e9 100644 --- a/src/matrixrtc/NewMembershipManager.ts +++ b/src/matrixrtc/NewMembershipManager.ts @@ -19,7 +19,7 @@ import { UpdateDelayedEventAction } from "../@types/requests.ts"; import { type MatrixClient } from "../client.ts"; import { UnsupportedDelayedEventsEndpointError } from "../errors.ts"; import { ConnectionError, HTTPError, MatrixError } from "../http-api/errors.ts"; -import { logger as rootLogger } from "../logger.ts"; +import { type Logger, logger as rootLogger } from "../logger.ts"; import { type Room } from "../models/room.ts"; import { defer, type IDeferred } from "../utils.ts"; import { type CallMembership, DEFAULT_EXPIRE_DURATION, type SessionMembershipData } from "./CallMembership.ts"; @@ -35,8 +35,6 @@ import { type MembershipManagerEventHandlerMap, } from "./IMembershipManager.ts"; -const logger = rootLogger.getChild("MatrixRTCSession"); - /* MembershipActionTypes: On Join: ───────────────┐ ┌───────────────(1)───────────┐ @@ -146,6 +144,8 @@ export class MembershipManager implements IMembershipManager { private activated = false; + private logger: Logger; + public isActivated(): boolean { return this.activated; } @@ -164,7 +164,7 @@ export class MembershipManager */ public join(fociPreferred: Focus[], focusActive?: Focus, onError?: (error: unknown) => void): void { if (this.scheduler.running) { - logger.error("MembershipManager is already running. Ignoring join request."); + this.logger.error("MembershipManager is already running. Ignoring join request."); return; } this.fociPreferred = fociPreferred; @@ -177,7 +177,7 @@ export class MembershipManager this.scheduler .startWithJoin() .catch((e) => { - logger.error("MembershipManager stopped because: ", e); + this.logger.error("MembershipManager stopped because: ", e); onError?.(e); }) .finally(() => { @@ -201,7 +201,7 @@ export class MembershipManager */ public leave(timeout?: number): Promise { if (!this.scheduler.running) { - logger.warn("Called MembershipManager.leave() even though the MembershipManager is not running"); + this.logger.warn("Called MembershipManager.leave() even though the MembershipManager is not running"); return Promise.resolve(true); } @@ -228,9 +228,9 @@ export class MembershipManager MembershipActionType.SendDelayedEvent, MembershipActionType.SendJoinEvent, ]; - logger.warn("Missing own membership: force re-join"); + this.logger.warn("Missing own membership: force re-join"); if (this.scheduler.actions.find((a) => sendingMembershipActions.includes(a.type as MembershipActionType))) { - logger.error( + this.logger.error( "NewMembershipManger tried adding another `SendFirstDelayedEvent` actions even though we already have one in the Queue\nActionQueueOnMemberUpdate:", this.scheduler.actions, ); @@ -252,7 +252,7 @@ export class MembershipManager return oldestMembership?.getPreferredFoci()[0]; } } else { - logger.warn("Unknown own ActiveFocus type. This makes it impossible to connect to an SFU."); + this.logger.warn("Unknown own ActiveFocus type. This makes it impossible to connect to an SFU."); } } else { // We do not understand the membership format (could be legacy). We default to oldestMembership @@ -281,16 +281,38 @@ export class MembershipManager | "_unstable_updateDelayedEvent" >, private getOldestMembership: () => CallMembership | undefined, + parentLogger?: Logger, ) { super(); + this.logger = (parentLogger ?? rootLogger).getChild(`[NewMembershipManager]`); const [userId, deviceId] = [this.client.getUserId(), this.client.getDeviceId()]; if (userId === null) throw Error("Missing userId in client"); if (deviceId === null) throw Error("Missing deviceId in client"); this.deviceId = deviceId; this.stateKey = this.makeMembershipStateKey(userId, deviceId); this.state = MembershipManager.defaultState; + this.scheduler = new ActionScheduler((type): Promise => { + if (this.oldStatus) { + // we put this at the beginning of the actions scheduler loop handle callback since it is a loop this + // is equivalent to running it at the end of the loop. (just after applying the status/action list changes) + // This order is required because this method needs to return the action updates. + this.logger.debug( + `MembershipManager applied action changes. Status: ${this.oldStatus} -> ${this.status}`, + ); + if (this.oldStatus !== this.status) { + this.emit(MembershipManagerEvent.StatusChanged, this.oldStatus, this.status); + } + } + this.oldStatus = this.status; + this.logger.debug(`MembershipManager before processing action. status=${this.oldStatus}`); + return this.membershipLoopHandler(type); + }, this.logger); } + // scheduler + private oldStatus?: Status; + private scheduler: ActionScheduler; + // MembershipManager mutable state. private state: MembershipManagerState; private static get defaultState(): MembershipManagerState { @@ -346,23 +368,6 @@ export class MembershipManager return this.joinConfig?.maximumNetworkErrorRetryCount ?? 10; } - // Scheduler: - private oldStatus?: Status; - private scheduler = new ActionScheduler((type): Promise => { - if (this.oldStatus) { - // we put this at the beginning of the actions scheduler loop handle callback since it is a loop this - // is equivalent to running it at the end of the loop. (just after applying the status/action list changes) - // This order is required because this method needs to return the action updates. - logger.debug(`MembershipManager applied action changes. Status: ${this.oldStatus} -> ${this.status}`); - if (this.oldStatus !== this.status) { - this.emit(MembershipManagerEvent.StatusChanged, this.oldStatus, this.status); - } - } - this.oldStatus = this.status; - logger.debug(`MembershipManager before processing action. status=${this.oldStatus}`); - return this.membershipLoopHandler(type); - }); - // LOOP HANDLER: private async membershipLoopHandler(type: MembershipActionType): Promise { switch (type) { @@ -468,9 +473,9 @@ export class MembershipManager // This action was scheduled because we are in the process of joining // log and fall through if (this.isUnsupportedDelayedEndpoint(e)) { - logger.info("Not using delayed event because the endpoint is not supported"); + this.logger.info("Not using delayed event because the endpoint is not supported"); } else { - logger.info("Not using delayed event because: " + e); + this.logger.info("Not using delayed event because: " + e); } // On any other error we fall back to not using delayed events and send the join state event immediately return createInsertActionUpdate(MembershipActionType.SendJoinEvent); @@ -561,7 +566,7 @@ export class MembershipManager if (update) return update; // On any other error we fall back to SendLeaveEvent (this includes hard errors from rate limiting) - logger.warn( + this.logger.warn( "Encountered unexpected error during SendScheduledDelayedLeaveEvent. Falling back to SendLeaveEvent", e, ); @@ -695,7 +700,7 @@ export class MembershipManager if (typeof maxDelayAllowed === "number" && this.membershipServerSideExpiryTimeout > maxDelayAllowed) { this.membershipServerSideExpiryTimeoutOverride = maxDelayAllowed; } - logger.warn("Retry sending delayed disconnection event due to server timeout limitations:", error); + this.logger.warn("Retry sending delayed disconnection event due to server timeout limitations:", error); return true; } return false; @@ -737,9 +742,9 @@ export class MembershipManager const defaultMs = 5000; try { resendDelay = error.getRetryAfterMs() ?? defaultMs; - logger.info(`Rate limited by server, retrying in ${resendDelay}ms`); + this.logger.info(`Rate limited by server, retrying in ${resendDelay}ms`); } catch (e) { - logger.warn( + this.logger.warn( `Error while retrieving a rate-limit retry delay, retrying after default delay of ${defaultMs}`, e, ); @@ -767,7 +772,7 @@ export class MembershipManager const retryDurationString = this.callMemberEventRetryDelayMinimum / 1000 + "s"; const retryCounterString = "(" + retries + "/" + this.maximumNetworkErrorRetryCount + ")"; if (error instanceof Error && error.name === "AbortError") { - logger.warn( + this.logger.warn( "Network local timeout error while sending event, retrying in " + retryDurationString + " " + @@ -785,12 +790,12 @@ export class MembershipManager // // A proper fix would be to either find a place to convert the `HttpError` into a `MatrixError` and the `processError` // method to handle it as expected or to adjust `processError` to also process `HttpError`'s. - logger.warn( + this.logger.warn( "delayed event update timeout error, retrying in " + retryDurationString + " " + retryCounterString, error, ); } else if (error instanceof ConnectionError) { - logger.warn( + this.logger.warn( "Network connection error while sending event, retrying in " + retryDurationString + " " + @@ -803,7 +808,7 @@ export class MembershipManager error.httpStatus >= 500 && error.httpStatus < 600 ) { - logger.warn( + this.logger.warn( "Server error while sending event, retrying in " + retryDurationString + " " + retryCounterString, error, ); @@ -879,7 +884,7 @@ export class MembershipManager return Status.Disconnected; } - logger.error("MembershipManager has an unknown state. Actions: ", actions); + this.logger.error("MembershipManager has an unknown state. Actions: ", actions); return Status.Unknown; } } diff --git a/src/matrixrtc/NewMembershipManagerActionScheduler.ts b/src/matrixrtc/NewMembershipManagerActionScheduler.ts index 7ed119503c1..28e2d3d2260 100644 --- a/src/matrixrtc/NewMembershipManagerActionScheduler.ts +++ b/src/matrixrtc/NewMembershipManagerActionScheduler.ts @@ -1,10 +1,8 @@ -import { logger as rootLogger } from "../logger.ts"; +import { type Logger, logger as rootLogger } from "../logger.ts"; import { type EmptyObject } from "../matrix.ts"; import { sleep } from "../utils.ts"; import { MembershipActionType } from "./NewMembershipManager.ts"; -const logger = rootLogger.getChild("MatrixRTCSession"); - /** @internal */ export interface Action { /** @@ -40,6 +38,7 @@ export type ActionUpdate = * @internal */ export class ActionScheduler { + private logger: Logger; /** * This is tracking the state of the scheduler loop. * Only used to prevent starting the loop twice. @@ -49,11 +48,14 @@ export class ActionScheduler { public constructor( /** This is the callback called for each scheduled action (`this.addAction()`) */ private membershipLoopHandler: (type: MembershipActionType) => Promise, - ) {} + parentLogger?: Logger, + ) { + this.logger = (parentLogger ?? rootLogger).getChild(`[NewMembershipActionScheduler]`); + } // function for the wakeup mechanism (in case we add an action externally and need to leave the current sleep) private wakeup: (update: ActionUpdate) => void = (update: ActionUpdate): void => { - logger.error("Cannot call wakeup before calling `startWithJoin()`"); + this.logger.error("Cannot call wakeup before calling `startWithJoin()`"); }; private _actions: Action[] = []; public get actions(): Action[] { @@ -69,7 +71,7 @@ export class ActionScheduler { */ public async startWithJoin(): Promise { if (this.running) { - logger.error("Cannot call startWithJoin() on NewMembershipActionScheduler while already running"); + this.logger.error("Cannot call startWithJoin() on NewMembershipActionScheduler while already running"); return; } this.running = true; @@ -92,7 +94,7 @@ export class ActionScheduler { let handlerResult: ActionUpdate = {}; if (!wakeupUpdate) { - logger.debug( + this.logger.debug( `Current MembershipManager processing: ${nextAction.type}\nQueue:`, this._actions, `\nDate.now: "${Date.now()}`, @@ -121,7 +123,7 @@ export class ActionScheduler { this.running = false; } - logger.debug("Leave MembershipManager ActionScheduler loop (no more actions)"); + this.logger.debug("Leave MembershipManager ActionScheduler loop (no more actions)"); } public initiateJoin(): void { diff --git a/src/matrixrtc/RoomKeyTransport.ts b/src/matrixrtc/RoomKeyTransport.ts index e98207433be..3e1ad31e856 100644 --- a/src/matrixrtc/RoomKeyTransport.ts +++ b/src/matrixrtc/RoomKeyTransport.ts @@ -18,7 +18,7 @@ import type { MatrixClient } from "../client.ts"; import type { EncryptionKeysEventContent, Statistics } from "./types.ts"; import { EventType } from "../@types/event.ts"; import { type MatrixError } from "../http-api/errors.ts"; -import { logger, type Logger } from "../logger.ts"; +import { logger as rootLogger, type Logger } from "../logger.ts"; import { KeyTransportEvents, type KeyTransportEventsHandlerMap, type IKeyTransport } from "./IKeyTransport.ts"; import { type MatrixEvent } from "../models/event.ts"; import { type CallMembership } from "./CallMembership.ts"; @@ -29,7 +29,7 @@ export class RoomKeyTransport extends TypedEventEmitter implements IKeyTransport { - private readonly prefixedLogger: Logger; + private readonly logger: Logger; public constructor( private room: Pick, @@ -38,9 +38,10 @@ export class RoomKeyTransport "sendEvent" | "getDeviceId" | "getUserId" | "cancelPendingEvent" | "decryptEventIfNeeded" >, private statistics: Statistics, + parentLogger?: Logger, ) { super(); - this.prefixedLogger = logger.getChild(`[RTC: ${room.roomId} RoomKeyTransport]`); + this.logger = (parentLogger ?? rootLogger).getChild(`[RoomKeyTransport]`); } public start(): void { this.room.on(RoomEvent.Timeline, (ev) => void this.consumeCallEncryptionEvent(ev)); @@ -54,23 +55,23 @@ export class RoomKeyTransport if (event.isDecryptionFailure()) { if (!isRetry) { - logger.warn( + this.logger.warn( `Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason} will retry once only`, ); // retry after 1 second. After this we give up. setTimeout(() => void this.consumeCallEncryptionEvent(event, true), 1000); } else { - logger.warn(`Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason}`); + this.logger.warn(`Decryption failed for event ${event.getId()}: ${event.decryptionFailureReason}`); } return; } else if (isRetry) { - logger.info(`Decryption succeeded for event ${event.getId()} after retry`); + this.logger.info(`Decryption succeeded for event ${event.getId()} after retry`); } if (event.getType() !== EventType.CallEncryptionKeysPrefix) return Promise.resolve(); if (!this.room) { - logger.error(`Got room state event for unknown room ${event.getRoomId()}!`); + this.logger.error(`Got room state event for unknown room ${event.getRoomId()}!`); return Promise.resolve(); } @@ -95,7 +96,7 @@ export class RoomKeyTransport try { await this.client.sendEvent(this.room.roomId, EventType.CallEncryptionKeysPrefix, content); } catch (error) { - this.prefixedLogger.error("Failed to send call encryption keys", error); + this.logger.error("Failed to send call encryption keys", error); const matrixError = error as MatrixError; if (matrixError.event) { // cancel the pending event: we'll just generate a new one with our latest @@ -114,20 +115,20 @@ export class RoomKeyTransport const callId = content["call_id"]; if (!userId) { - logger.warn(`Received m.call.encryption_keys with no userId: callId=${callId}`); + this.logger.warn(`Received m.call.encryption_keys with no userId: callId=${callId}`); return; } // We currently only handle callId = "" (which is the default for room scoped calls) if (callId !== "") { - logger.warn( + this.logger.warn( `Received m.call.encryption_keys with unsupported callId: userId=${userId}, deviceId=${deviceId}, callId=${callId}`, ); return; } if (!Array.isArray(content.keys)) { - logger.warn(`Received m.call.encryption_keys where keys wasn't an array: callId=${callId}`); + this.logger.warn(`Received m.call.encryption_keys where keys wasn't an array: callId=${callId}`); return; } @@ -135,7 +136,7 @@ export class RoomKeyTransport // We store our own sender key in the same set along with keys from others, so it's // important we don't allow our own keys to be set by one of these events (apart from // the fact that we don't need it anyway because we already know our own keys). - logger.info("Ignoring our own keys event"); + this.logger.info("Ignoring our own keys event"); return; } @@ -145,7 +146,7 @@ export class RoomKeyTransport for (const key of content.keys) { if (!key) { - logger.info("Ignoring false-y key in keys event"); + this.logger.info("Ignoring false-y key in keys event"); continue; } @@ -163,11 +164,11 @@ export class RoomKeyTransport typeof encryptionKey !== "string" || typeof encryptionKeyIndex !== "number" ) { - logger.warn( + this.logger.warn( `Malformed call encryption_key: userId=${userId}, deviceId=${deviceId}, encryptionKeyIndex=${encryptionKeyIndex} callId=${callId}`, ); } else { - logger.debug( + this.logger.debug( `onCallEncryption userId=${userId}:${deviceId} encryptionKeyIndex=${encryptionKeyIndex} age=${age}ms`, ); this.emit( diff --git a/src/matrixrtc/ToDeviceKeyTransport.ts b/src/matrixrtc/ToDeviceKeyTransport.ts index 671d41d6cfa..0ba06805c93 100644 --- a/src/matrixrtc/ToDeviceKeyTransport.ts +++ b/src/matrixrtc/ToDeviceKeyTransport.ts @@ -16,7 +16,7 @@ limitations under the License. import { TypedEventEmitter } from "../models/typed-event-emitter.ts"; import { type IKeyTransport, KeyTransportEvents, type KeyTransportEventsHandlerMap } from "./IKeyTransport.ts"; -import { type Logger } from "../logger.ts"; +import { type Logger, logger as rootLogger } from "../logger.ts"; import type { CallMembership } from "./CallMembership.ts"; import type { EncryptionKeysToDeviceEventContent, Statistics } from "./types.ts"; import { ClientEvent, type MatrixClient } from "../client.ts"; @@ -31,7 +31,7 @@ export class ToDeviceKeyTransport extends TypedEventEmitter implements IKeyTransport { - private readonly prefixedLogger: Logger; + private readonly logger: Logger; public constructor( private userId: string, @@ -39,10 +39,10 @@ export class ToDeviceKeyTransport private roomId: string, private client: Pick, private statistics: Statistics, - logger: Logger, + parentLogger?: Logger, ) { super(); - this.prefixedLogger = logger.getChild(`[${roomId} ToDeviceKeyTransport]`); + this.logger = (parentLogger ?? rootLogger).getChild(`[ToDeviceKeyTransport]`); } public start(): void { @@ -74,7 +74,7 @@ export class ToDeviceKeyTransport .filter((member) => { // filter malformed call members if (member.sender == undefined || member.deviceId == undefined) { - this.prefixedLogger.warn(`Malformed call member: ${member.sender}|${member.deviceId}`); + this.logger.warn(`Malformed call member: ${member.sender}|${member.deviceId}`); return false; } // Filter out me @@ -91,7 +91,7 @@ export class ToDeviceKeyTransport await this.client.encryptAndSendToDevice(EventType.CallEncryptionKeysPrefix, targets, content); this.statistics.counters.roomEventEncryptionKeysSent += 1; } else { - this.prefixedLogger.warn("No targets found for sending key"); + this.logger.warn("No targets found for sending key"); } } @@ -145,21 +145,21 @@ export class ToDeviceKeyTransport const roomId = content.room_id; if (!roomId) { // Invalid event - this.prefixedLogger.warn("Malformed Event: invalid call encryption keys event, no roomId"); + this.logger.warn("Malformed Event: invalid call encryption keys event, no roomId"); return; } if (roomId !== this.roomId) { - this.prefixedLogger.warn("Malformed Event: Mismatch roomId"); + this.logger.warn("Malformed Event: Mismatch roomId"); return; } if (!content.keys || !content.keys.key || typeof content.keys.index !== "number") { - this.prefixedLogger.warn("Malformed Event: Missing keys field"); + this.logger.warn("Malformed Event: Missing keys field"); return; } if (!content.member || !content.member.claimed_device_id) { - this.prefixedLogger.warn("Malformed Event: Missing claimed_device_id"); + this.logger.warn("Malformed Event: Missing claimed_device_id"); return; } From f8c9d1ad83d798056f0df31b807bc5fcfd5212cc Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 10 Apr 2025 15:16:54 +0200 Subject: [PATCH 2/6] tests: Add more RTC key transport tests --- spec/unit/matrixrtc/RoomKeyTransport.spec.ts | 75 ++++++++++++++++++- .../matrixrtc/ToDeviceKeyTransport.spec.ts | 12 +-- 2 files changed, 80 insertions(+), 7 deletions(-) diff --git a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts index 0d0db2e4fff..3d08f8ff5c9 100644 --- a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts +++ b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts @@ -18,7 +18,7 @@ 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"; describe("RoomKeyTransport", () => { let client: MatrixClient; @@ -138,4 +138,77 @@ 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(onCallEncryptionMock).toHaveBeenCalledTimes(0); + }); + }); }); diff --git a/spec/unit/matrixrtc/ToDeviceKeyTransport.spec.ts b/spec/unit/matrixrtc/ToDeviceKeyTransport.spec.ts index ae165152cb1..e120eeb887d 100644 --- a/spec/unit/matrixrtc/ToDeviceKeyTransport.spec.ts +++ b/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" }, }, ]; From d7fc9398baba7e2b44c0eb3aa37ee7d257765818 Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 10 Apr 2025 15:42:49 +0200 Subject: [PATCH 3/6] test: improve rtc key room transport test --- spec/unit/matrixrtc/RoomKeyTransport.spec.ts | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts index 3d08f8ff5c9..b2b00200a16 100644 --- a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts +++ b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts @@ -19,6 +19,8 @@ import { RoomKeyTransport } from "../../../src/matrixrtc/RoomKeyTransport"; import { KeyTransportEvents } from "../../../src/matrixrtc/IKeyTransport"; import { EventType, MatrixClient, RoomEvent } 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; @@ -26,9 +28,16 @@ describe("RoomKeyTransport", () => { emitTimelineEvent: (event: MatrixEvent) => void; }; let transport: RoomKeyTransport; + let mockLogger: Mocked; + const onCallEncryptionMock = jest.fn(); beforeEach(() => { onCallEncryptionMock.mockReset(); + mockLogger = { + debug: jest.fn(), + warn: jest.fn(), + } as unknown as Mocked; + const statistics = { counters: { roomEventEncryptionKeysSent: 0, @@ -41,7 +50,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); transport.on(KeyTransportEvents.ReceivedKeys, (...p) => { onCallEncryptionMock(...p); }); @@ -208,6 +219,7 @@ describe("RoomKeyTransport", () => { test.each(MALFORMED_EVENT)("should warn on malformed event %j", (event) => { transport.onEncryptionEvent(event); + expect(mockLogger.warn).toHaveBeenCalled(); expect(onCallEncryptionMock).toHaveBeenCalledTimes(0); }); }); From 6868537e1d171b8f217c29c9e6b87065103d0c63 Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 10 Apr 2025 15:47:39 +0200 Subject: [PATCH 4/6] fixup: missing mock --- spec/unit/matrixrtc/RoomKeyTransport.spec.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts index b2b00200a16..f08cced850d 100644 --- a/spec/unit/matrixrtc/RoomKeyTransport.spec.ts +++ b/spec/unit/matrixrtc/RoomKeyTransport.spec.ts @@ -36,6 +36,7 @@ describe("RoomKeyTransport", () => { mockLogger = { debug: jest.fn(), warn: jest.fn(), + info: jest.fn(), } as unknown as Mocked; const statistics = { From 9b56650e5180cb21d1c8084872594aacedf0e258 Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 10 Apr 2025 16:37:09 +0200 Subject: [PATCH 5/6] rtc: more tests --- spec/unit/matrixrtc/MembershipManager.spec.ts | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/spec/unit/matrixrtc/MembershipManager.spec.ts b/spec/unit/matrixrtc/MembershipManager.spec.ts index 265289141c1..f0173506c3a 100644 --- a/spec/unit/matrixrtc/MembershipManager.spec.ts +++ b/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, returnVal?: Promise) { return new Promise((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); +}); From db5d26b28099912befd2ea86cadf06f6c21ea27a Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 10 Apr 2025 16:55:07 +0200 Subject: [PATCH 6/6] coverage trick --- spec/unit/matrixrtc/MatrixRTCSession.spec.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/spec/unit/matrixrtc/MatrixRTCSession.spec.ts b/spec/unit/matrixrtc/MatrixRTCSession.spec.ts index 7dee5ccaa46..3508e01a648 100644 --- a/spec/unit/matrixrtc/MatrixRTCSession.spec.ts +++ b/spec/unit/matrixrtc/MatrixRTCSession.spec.ts @@ -993,6 +993,7 @@ describe("MatrixRTCSession", () => { sess!.joinRoomSession([mockFocus], mockFocus, { manageMediaKeys: true, + useNewMembershipManager: true, useExperimentalToDeviceTransport: true, });