From a91bcf5d221e3109df19571731b537d97bfca18e Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 12:44:13 +0100 Subject: [PATCH 01/12] ensure there is no race between reconnecting & updating the session id it's probably fine as connect has to wait to receive the negotiationneeded event before it can send out an invite, but just to be sure update the session id beforehand --- src/matrix/calls/group/Member.ts | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index 3d773b7e..694201a9 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -131,24 +131,28 @@ export class Member { updateCallInfo(callDeviceMembership: CallDeviceMembership, log: ILogItem) { log.wrap({l: "updateing device membership", deviceId: this.deviceId}, log => { // session id is changing, disconnect so we start with a new slate for the new session - if (callDeviceMembership.session_id !== this.sessionId) { + const oldSessionId = this.sessionId; + this.callDeviceMembership = callDeviceMembership; + if (oldSessionId !== this.sessionId) { log.wrap({ l: "member event changes session id", - oldSessionId: this.sessionId, - newSessionId: callDeviceMembership.session_id + oldSessionId, + newSessionId: this.sessionId }, log => { // prevent localMedia from being stopped // as connect won't be called again when reconnecting // to the new session - const localMedia = this.localMedia; + const localMedia = this.localMedia!; this.localMedia = undefined; + // don't send a hangup event, as the old session id client is offline already + // and we'd send it with the wrong session id anyway as callDeviceMembership + // has already been replaced. this.disconnect(false); // connect again, as the other side might be waiting for our invite // after refreshing - this.connect(localMedia!, this.localMuteSettings!); + this.connect(localMedia, this.localMuteSettings!); }); } - this.callDeviceMembership = callDeviceMembership; }); } From 0be75d9c5937ac71a1419fc8e08a2358a9b7bc5b Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 12:45:15 +0100 Subject: [PATCH 02/12] update the TODO --- src/matrix/calls/TODO.md | 52 +++++++++++++++++++++++++++++++++------- 1 file changed, 44 insertions(+), 8 deletions(-) diff --git a/src/matrix/calls/TODO.md b/src/matrix/calls/TODO.md index 91840af7..728c7dc2 100644 --- a/src/matrix/calls/TODO.md +++ b/src/matrix/calls/TODO.md @@ -11,23 +11,59 @@ - DONE: implement receiving hangup - DONE: implement cloning the localMedia so it works in safari? - DONE: implement 3 retries per peer - - implement muting tracks with m.call.sdp_stream_metadata_changed - - implement renegotiation - - making logging better + - DONE: implement muting tracks with m.call.sdp_stream_metadata_changed + - DONE: implement renegotiation - DONE: finish session id support - call peers are essentially identified by (userid, deviceid, sessionid). If see a new session id, we first disconnect from the current member so we're ready to connect with a clean slate again (in a member event, also in to_device? no harm I suppose, given olm encryption ensures you can't spoof the deviceid). + - making logging better + - figure out why sometimes leave button does not work + - get correct members and avatars in call + - improve UI while in a call + - allow toggling audio + - support active speaker, sort speakers by last active + - close muted media stream after a while + - support highlight mode where we show active speaker and thumbnails for other participants + - better grid mode: + - we report the call view size to the view model with ResizeObserver, we calculate the A/R + - we calculate the grid based on view A/R, taking into account minimal stream size + - show name on stream view + - when you start a call, or join one, first you go to a SelectCallMedia screen where you can pick whether you want to use camera, audio or both: + - if you are joining a call, we'll default to the call intent + - if you are creating a call, we'll default to video + - when creating a call, adjust the navigation path to room/room_id/call + - when selecting a call, adjust the navigation path to room/room_id/call/call_id - implement to_device messages arriving before m.call(.member) state event + - DONE for m.call.member, not for m.call and not for to_device other than m.call.invite arriving before invite - reeable crypto & implement fetching olm keys before sending encrypted signalling message - local echo for join/leave buttons? - - make UI pretsy - - figure out video layout - - figure out nav structure - batch outgoing to_device messages in one request to homeserver for operations that will send out an event to all participants (e.g. mute) + - implement call ringing and rejecting a ringing call + - support screen sharing + - add button to enable, disable + - support showing stream view with large screen share video element and small camera video element (if present) - don't load all members when loading calls to know whether they are ringing and joined by ourself - only load our own member once, then have a way to load additional members on a call. - see if we remove partyId entirely, it is only used for detecting remote echo which is not an issue for group calls? see https://github.com/matrix-org/matrix-spec-proposals/blob/dbkr/msc2746/proposals/2746-reliable-voip.md#add-party_id-to-all-voip-events + - remove PeerCall.waitForState ? + - invite glare is completely untested, does it work? + - how to remove call from m.call.member when just closing client? + - when closing client and still in call, tell service worker to send event on our behalf? + ```js + // dispose when leaving call + this.track(platform.registerExitHandler(unloadActions => { + // batch requests will resolve immediately, + // so we can reuse the same send code that does awaits without awaiting? + const batch = new RequestBatch(); + const hsApi = this.hsApi.withBatch(batch); + // _leaveCallMemberContent will need to become sync, + // so we'll need to keep track of own member event rather than rely on storage + hsApi.sendStateEvent("m.call.member", this._leaveCallMemberContent()); + // does this internally: serviceWorkerHandler.trySend("sendRequestBatch", batch.toJSON()); + unloadActions.sendRequestBatch(batch); + })); + ``` ## TODO (old) - - PeerCall + - DONE: PeerCall - send invite - implement terminate - implement waitForState @@ -46,7 +82,7 @@ - handle remote track being muted - handle adding/removing tracks to an ongoing call - handle sdp metadata - - Participant + - DONE: Participant - handle glare - encrypt to_device message with olm - batch outgoing to_device messages in one request to homeserver for operations that will send out an event to all participants (e.g. mute) From 2d9b69751f58f6419b41364a9fa43534d066d080 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 16:52:00 +0100 Subject: [PATCH 03/12] some logging cleanup --- src/matrix/calls/group/GroupCall.ts | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index fa7f4f9d..4531a95c 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -329,15 +329,14 @@ export class GroupCall extends EventEmitter<{change: never}> { /** @internal */ private removeMemberDevice(userId: string, deviceId: string, log: ILogItem) { const memberKey = getMemberKey(userId, deviceId); - log.wrap({l: "removeMemberDevice", id: memberKey}, log => { - const member = this._members.get(memberKey); - if (member) { - log.set("leave", true); - this._members.remove(memberKey); - member.disconnect(false); - } - this.emitChange(); - }); + log.set("id", memberKey); + const member = this._members.get(memberKey); + if (member) { + log.set("leave", true); + this._members.remove(memberKey); + member.disconnect(false); + } + this.emitChange(); } /** @internal */ From 3d83fda69fc5fba9c3f184b06bcb11f27c7ab9f4 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 16:52:17 +0100 Subject: [PATCH 04/12] some more cleanup --- src/matrix/calls/group/Member.ts | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index 694201a9..d6951fb8 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -123,7 +123,9 @@ export class Member { this.peerCall = undefined; this.localMedia?.dispose(); this.localMedia = undefined; + this.localMuteSettings = undefined; this.retryCount = 0; + this.logItem.finish(); }); } @@ -158,8 +160,12 @@ export class Member { /** @internal */ emitUpdate = (peerCall: PeerCall, params: any) => { + // these must be set as the update comes from the peerCall, + // which only exists when these are set + const localMedia = this.localMedia!; + const localMuteSettings = this.localMuteSettings!; if (peerCall.state === CallState.Ringing) { - peerCall.answer(this.localMedia!, this.localMuteSettings!); + peerCall.answer(localMedia, localMuteSettings); } else if (peerCall.state === CallState.Ended) { const hangupReason = peerCall.hangupReason; @@ -168,7 +174,7 @@ export class Member { if (hangupReason && !errorCodesWithoutRetry.includes(hangupReason)) { this.retryCount += 1; if (this.retryCount <= 3) { - this.connect(this.localMedia!, this.localMuteSettings!); + this.connect(localMedia, localMuteSettings); } } } From d346f4a3fb0f80694f0536a717eae25f3a991c04 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 16:52:42 +0100 Subject: [PATCH 05/12] add & remove rather than update when session id changed --- src/matrix/calls/group/GroupCall.ts | 11 +++++++++-- src/matrix/calls/group/Member.ts | 22 ---------------------- 2 files changed, 9 insertions(+), 24 deletions(-) diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index 4531a95c..4373cd4e 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -233,10 +233,17 @@ export class GroupCall extends EventEmitter<{change: never}> { } } else { let member = this._members.get(memberKey); - if (member) { + const sessionIdChanged = member && member.sessionId !== device.session_id; + if (member && !sessionIdChanged) { log.set("update", true); - member!.updateCallInfo(device, log); + member.updateCallInfo(device, log); } else { + if (member && sessionIdChanged) { + log.set("removedSessionId", member.sessionId); + member.disconnect(false); + this._members.remove(memberKey); + member = undefined; + } const logItem = this.logItem.child({l: "member", id: memberKey}); log.set("add", true); log.refDetached(logItem); diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index d6951fb8..79d91fa1 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -132,29 +132,7 @@ export class Member { /** @internal */ updateCallInfo(callDeviceMembership: CallDeviceMembership, log: ILogItem) { log.wrap({l: "updateing device membership", deviceId: this.deviceId}, log => { - // session id is changing, disconnect so we start with a new slate for the new session - const oldSessionId = this.sessionId; this.callDeviceMembership = callDeviceMembership; - if (oldSessionId !== this.sessionId) { - log.wrap({ - l: "member event changes session id", - oldSessionId, - newSessionId: this.sessionId - }, log => { - // prevent localMedia from being stopped - // as connect won't be called again when reconnecting - // to the new session - const localMedia = this.localMedia!; - this.localMedia = undefined; - // don't send a hangup event, as the old session id client is offline already - // and we'd send it with the wrong session id anyway as callDeviceMembership - // has already been replaced. - this.disconnect(false); - // connect again, as the other side might be waiting for our invite - // after refreshing - this.connect(localMedia, this.localMuteSettings!); - }); - } }); } From e1974711f392c821ec08cf2c3f5908db967a168d Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Thu, 28 Apr 2022 16:56:32 +0100 Subject: [PATCH 06/12] dont close this when disconnecting as long as we haven't restructured the log items in general, we can always connect again fr now and assume to reuse the same log item --- src/matrix/calls/group/Member.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index 79d91fa1..314734d8 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -125,7 +125,6 @@ export class Member { this.localMedia = undefined; this.localMuteSettings = undefined; this.retryCount = 0; - this.logItem.finish(); }); } From 8e2e92cd2c1c503fecf7ef76f4081d8cc4a7ed37 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 29 Apr 2022 10:11:12 +0100 Subject: [PATCH 07/12] this timer should not fire after disposing --- src/matrix/calls/PeerCall.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/src/matrix/calls/PeerCall.ts b/src/matrix/calls/PeerCall.ts index e5e70a46..d69cafa6 100644 --- a/src/matrix/calls/PeerCall.ts +++ b/src/matrix/calls/PeerCall.ts @@ -1045,6 +1045,7 @@ export class PeerCall implements IDisposable { public dispose(): void { this.disposables.dispose(); + this.iceDisconnectedTimeout?.abort(); this.peerConnection.close(); } From bb92d2e30d5d725db8745945f76ec794b20300d6 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 29 Apr 2022 14:19:03 +0100 Subject: [PATCH 08/12] log session id when adding a member entry --- src/matrix/calls/group/GroupCall.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index 4373cd4e..99e907fe 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -244,7 +244,7 @@ export class GroupCall extends EventEmitter<{change: never}> { this._members.remove(memberKey); member = undefined; } - const logItem = this.logItem.child({l: "member", id: memberKey}); + const logItem = this.logItem.child({l: "member", id: memberKey, sessionId: device.session_id}); log.set("add", true); log.refDetached(logItem); member = new Member( From 9938071e1cdc82e53c007ea99578334f5cd6f123 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 29 Apr 2022 14:34:03 +0100 Subject: [PATCH 09/12] more sessionId logging --- src/matrix/calls/group/GroupCall.ts | 3 ++- src/matrix/calls/group/Member.ts | 4 +++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index 99e907fe..707188f7 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -77,6 +77,7 @@ export class GroupCall extends EventEmitter<{change: never}> { ) { super(); logItem.set("id", this.id); + logItem.set("sessionId", this.options.sessionId); this._state = newCall ? GroupCallState.Fledgling : GroupCallState.Created; this._memberOptions = Object.assign({}, options, { confId: this.id, @@ -244,7 +245,7 @@ export class GroupCall extends EventEmitter<{change: never}> { this._members.remove(memberKey); member = undefined; } - const logItem = this.logItem.child({l: "member", id: memberKey, sessionId: device.session_id}); + const logItem = this.logItem.child({l: "member", id: memberKey}); log.set("add", true); log.refDetached(logItem); member = new Member( diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index 314734d8..28190967 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -60,7 +60,9 @@ export class Member { private callDeviceMembership: CallDeviceMembership, private readonly options: Options, private readonly logItem: ILogItem, - ) {} + ) { + this.logItem.set("sessionId", this.sessionId); + } get remoteMedia(): RemoteMedia | undefined { return this.peerCall?.remoteMedia; From c1c08e9eb0f58ac808fd9405804b46b62e4cf656 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 29 Apr 2022 14:57:45 +0100 Subject: [PATCH 10/12] more logging of callId and sessionIds --- src/matrix/calls/PeerCall.ts | 4 +++- src/matrix/calls/group/GroupCall.ts | 1 + src/matrix/calls/group/Member.ts | 4 ++++ 3 files changed, 8 insertions(+), 1 deletion(-) diff --git a/src/matrix/calls/PeerCall.ts b/src/matrix/calls/PeerCall.ts index d69cafa6..edc245a4 100644 --- a/src/matrix/calls/PeerCall.ts +++ b/src/matrix/calls/PeerCall.ts @@ -105,6 +105,7 @@ export class PeerCall implements IDisposable { private readonly options: Options, private readonly logItem: ILogItem, ) { + logItem.log({l: "create PeerCall", callId}); this._remoteMedia = new RemoteMedia(); this.peerConnection = options.webRTC.createPeerConnection(this.options.forceTURN, this.options.turnServers, 0); @@ -299,7 +300,7 @@ export class PeerCall implements IDisposable { } handleIncomingSignallingMessage(message: SignallingMessage, partyId: PartyId): Promise { - return this.logItem.wrap({l: "receive", id: message.type, partyId}, async log => { + return this.logItem.wrap({l: "receive", id: message.type, callId: message.content.call_id}, async log => { switch (message.type) { case EventType.Invite: if (this.callId !== message.content.call_id) { @@ -323,6 +324,7 @@ export class PeerCall implements IDisposable { break; case EventType.Hangup: // TODO: this is a bit hacky, double check its what we need + log.set("reason", message.content.reason); this.terminate(CallParty.Remote, message.content.reason ?? CallErrorCode.UserHangup, log); break; default: diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index 707188f7..12d0be51 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -242,6 +242,7 @@ export class GroupCall extends EventEmitter<{change: never}> { if (member && sessionIdChanged) { log.set("removedSessionId", member.sessionId); member.disconnect(false); + member.dispose(); this._members.remove(memberKey); member = undefined; } diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index 28190967..bed1af94 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -130,6 +130,10 @@ export class Member { }); } + dispose() { + this.logItem.finish(); + } + /** @internal */ updateCallInfo(callDeviceMembership: CallDeviceMembership, log: ILogItem) { log.wrap({l: "updateing device membership", deviceId: this.deviceId}, log => { From 1a0b11ff7ea9f5990b7b9dd170c0d735466fea68 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Fri, 29 Apr 2022 14:59:19 +0100 Subject: [PATCH 11/12] also log payload when receiving to_device call message, help debug with thirdroom --- src/matrix/calls/PeerCall.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/matrix/calls/PeerCall.ts b/src/matrix/calls/PeerCall.ts index edc245a4..c45529e9 100644 --- a/src/matrix/calls/PeerCall.ts +++ b/src/matrix/calls/PeerCall.ts @@ -300,7 +300,7 @@ export class PeerCall implements IDisposable { } handleIncomingSignallingMessage(message: SignallingMessage, partyId: PartyId): Promise { - return this.logItem.wrap({l: "receive", id: message.type, callId: message.content.call_id}, async log => { + return this.logItem.wrap({l: "receive", id: message.type, callId: message.content.call_id, payload: message}, async log => { switch (message.type) { case EventType.Invite: if (this.callId !== message.content.call_id) { From 1a08616df111a0b7df8cff2cdb773219dbcca9f7 Mon Sep 17 00:00:00 2001 From: Bruno Windels <274386+bwindels@users.noreply.github.com> Date: Wed, 4 May 2022 18:44:11 +0200 Subject: [PATCH 12/12] logging improvements --- scripts/logviewer/index.html | 31 ++-- scripts/logviewer/main.js | 9 +- src/domain/session/room/CallViewModel.ts | 8 +- src/logging/ConsoleLogger.ts | 2 + src/logging/NullLogger.ts | 6 + src/logging/types.ts | 2 + src/matrix/calls/CallHandler.ts | 16 +- src/matrix/calls/PeerCall.ts | 116 ++++++++------ src/matrix/calls/common.ts | 2 + src/matrix/calls/group/GroupCall.ts | 188 +++++++++++++--------- src/matrix/calls/group/Member.ts | 192 ++++++++++++++--------- src/platform/types/WebRTC.ts | 7 + 12 files changed, 359 insertions(+), 220 deletions(-) diff --git a/scripts/logviewer/index.html b/scripts/logviewer/index.html index 790c4508..08ba2f3c 100644 --- a/scripts/logviewer/index.html +++ b/scripts/logviewer/index.html @@ -162,6 +162,10 @@ --hue: 30deg; } + .timeline .item.type-call { + --hue: 50deg; + } + .timeline .item.type-navigation { --hue: 200deg; } @@ -188,19 +192,28 @@ nav form { display: inline; } + + #filename { + margin: 0; + font-size: 1rem; + padding: 4px 0; + }
diff --git a/scripts/logviewer/main.js b/scripts/logviewer/main.js index 4c6b3792..3ae860b2 100644 --- a/scripts/logviewer/main.js +++ b/scripts/logviewer/main.js @@ -163,6 +163,7 @@ function getRootItemHeader(prevItem, item) { async function loadFile() { const file = await openFile(); + document.getElementById("filename").innerText = file.name; const json = await readFileAsText(file); const logs = JSON.parse(json); logs.items.sort((a, b) => itemStart(a) - itemStart(b)); @@ -257,14 +258,16 @@ function itemShortErrorMessage(item) { } function itemCaption(item) { - if (itemType(item) === "network") { + if (itemLabel(item) && itemError(item)) { + return `${itemLabel(item)} (${itemShortErrorMessage(item)})`; + } if (itemType(item) === "network") { return `${itemValues(item)?.method} ${itemValues(item)?.url}`; } else if (itemLabel(item) && itemValues(item)?.id) { return `${itemLabel(item)} ${itemValues(item).id}`; } else if (itemLabel(item) && itemValues(item)?.status) { return `${itemLabel(item)} (${itemValues(item).status})`; - } else if (itemLabel(item) && itemError(item)) { - return `${itemLabel(item)} (${itemShortErrorMessage(item)})`; + } else if (itemLabel(item) && itemValues(item)?.type) { + return `${itemLabel(item)} (${itemValues(item)?.type})`; } else if (itemRef(item)) { const refItem = itemByRef.get(itemRef(item)); if (refItem) { diff --git a/src/domain/session/room/CallViewModel.ts b/src/domain/session/room/CallViewModel.ts index da526fcd..08bc3691 100644 --- a/src/domain/session/room/CallViewModel.ts +++ b/src/domain/session/room/CallViewModel.ts @@ -68,7 +68,9 @@ export class CallViewModel extends ViewModel { } async toggleVideo() { - this.call.setMuted(this.call.muteSettings.toggleCamera()); + if (this.call.muteSettings) { + this.call.setMuted(this.call.muteSettings.toggleCamera()); + } } } @@ -87,11 +89,11 @@ class OwnMemberViewModel extends ViewModel implements IStreamV } get isCameraMuted(): boolean { - return isMuted(this.call.muteSettings.camera, !!getStreamVideoTrack(this.stream)); + return isMuted(this.call.muteSettings?.camera, !!getStreamVideoTrack(this.stream)); } get isMicrophoneMuted(): boolean { - return isMuted(this.call.muteSettings.microphone, !!getStreamAudioTrack(this.stream)); + return isMuted(this.call.muteSettings?.microphone, !!getStreamAudioTrack(this.stream)); } get avatarLetter(): string { diff --git a/src/logging/ConsoleLogger.ts b/src/logging/ConsoleLogger.ts index 1d8232f9..7a3ae638 100644 --- a/src/logging/ConsoleLogger.ts +++ b/src/logging/ConsoleLogger.ts @@ -84,6 +84,8 @@ function itemCaption(item: ILogItem): string { return `${item.values.l} ${item.values.id}`; } else if (item.values.l && typeof item.values.status !== "undefined") { return `${item.values.l} (${item.values.status})`; + } else if (item.values.l && typeof item.values.type !== "undefined") { + return `${item.values.l} (${item.values.type})`; } else if (item.values.l && item.error) { return `${item.values.l} failed`; } else if (typeof item.values.ref !== "undefined") { diff --git a/src/logging/NullLogger.ts b/src/logging/NullLogger.ts index adc2b843..835f7314 100644 --- a/src/logging/NullLogger.ts +++ b/src/logging/NullLogger.ts @@ -65,12 +65,18 @@ export class NullLogItem implements ILogItem { } wrap(_: LabelOrValues, callback: LogCallback): T { + return this.run(callback); + } + + run(callback: LogCallback): T { return callback(this); } + log(): ILogItem { return this; } + set(): ILogItem { return this; } runDetached(_: LabelOrValues, callback: LogCallback): ILogItem { diff --git a/src/logging/types.ts b/src/logging/types.ts index 8e35dbf3..2b1d305d 100644 --- a/src/logging/types.ts +++ b/src/logging/types.ts @@ -42,6 +42,8 @@ export interface ILogItem { readonly start?: number; readonly values: LogItemValues; wrap(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): T; + /*** This is sort of low-level, you probably want to use wrap. If you do use it, it should only be called once. */ + run(callback: LogCallback): T; log(labelOrValues: LabelOrValues, logLevel?: LogLevel): ILogItem; set(key: string | object, value: unknown): ILogItem; runDetached(labelOrValues: LabelOrValues, callback: LogCallback, logLevel?: LogLevel, filterCreator?: FilterCreator): ILogItem; diff --git a/src/matrix/calls/CallHandler.ts b/src/matrix/calls/CallHandler.ts index 06e83d11..7fbe6103 100644 --- a/src/matrix/calls/CallHandler.ts +++ b/src/matrix/calls/CallHandler.ts @@ -21,6 +21,7 @@ import {handlesEventType} from "./PeerCall"; import {EventType, CallIntent} from "./callEventTypes"; import {GroupCall} from "./group/GroupCall"; import {makeId} from "../common"; +import {CALL_LOG_TYPE} from "./common"; import type {LocalMedia} from "./LocalMedia"; import type {Room} from "../room/Room"; @@ -36,7 +37,6 @@ import type {CallEntry} from "../storage/idb/stores/CallStore"; import type {Clock} from "../../platform/web/dom/Clock"; export type Options = Omit & { - logger: ILogger, clock: Clock }; @@ -78,7 +78,7 @@ export class CallHandler { } private async _loadCallEntries(callEntries: CallEntry[], txn: Transaction): Promise { - return this.options.logger.run("loading calls", async log => { + return this.options.logger.run({l: "loading calls", t: CALL_LOG_TYPE}, async log => { log.set("entries", callEntries.length); await Promise.all(callEntries.map(async callEntry => { if (this._calls.get(callEntry.callId)) { @@ -86,8 +86,7 @@ export class CallHandler { } const event = await txn.roomState.get(callEntry.roomId, EventType.GroupCall, callEntry.callId); if (event) { - const logItem = this.options.logger.child({l: "call", loaded: true}); - const call = new GroupCall(event.event.state_key, false, event.event.content, event.roomId, this.groupCallOptions, logItem); + const call = new GroupCall(event.event.state_key, false, event.event.content, event.roomId, this.groupCallOptions); this._calls.set(call.id, call); } })); @@ -108,11 +107,10 @@ export class CallHandler { } async createCall(roomId: string, type: "m.video" | "m.voice", name: string, intent: CallIntent = CallIntent.Ring): Promise { - const logItem = this.options.logger.child({l: "call", incoming: false}); const call = new GroupCall(makeId("conf-"), true, { "m.name": name, "m.intent": intent - }, roomId, this.groupCallOptions, logItem); + }, roomId, this.groupCallOptions); this._calls.set(call.id, call); try { @@ -129,7 +127,6 @@ export class CallHandler { } catch (err) { //if (err.name === "ConnectionError") { // if we're offline, give up and remove the call again - call.dispose(); this._calls.remove(call.id); //} throw err; @@ -181,13 +178,12 @@ export class CallHandler { if (call) { call.updateCallEvent(event.content, log); if (call.isTerminated) { - call.dispose(); + call.disconnect(log); this._calls.remove(call.id); txn.calls.remove(call.intent, roomId, call.id); } } else { - const logItem = this.options.logger.child({l: "call", incoming: true}); - call = new GroupCall(event.state_key, false, event.content, roomId, this.groupCallOptions, logItem); + call = new GroupCall(event.state_key, false, event.content, roomId, this.groupCallOptions); this._calls.set(call.id, call); txn.calls.add({ intent: call.intent, diff --git a/src/matrix/calls/PeerCall.ts b/src/matrix/calls/PeerCall.ts index c45529e9..963d6c30 100644 --- a/src/matrix/calls/PeerCall.ts +++ b/src/matrix/calls/PeerCall.ts @@ -49,7 +49,7 @@ export type Options = { forceTURN: boolean, turnServers: RTCIceServer[], createTimeout: TimeoutCreator, - emitUpdate: (peerCall: PeerCall, params: any) => void; + emitUpdate: (peerCall: PeerCall, params: any, log: ILogItem) => void; sendSignallingMessage: (message: SignallingMessage, log: ILogItem) => Promise; }; @@ -70,6 +70,7 @@ export class PeerCall implements IDisposable { // we don't own localMedia and should hence not call dispose on it from here private localMedia?: LocalMedia; private localMuteSettings?: MuteSettings; + // TODO: this should go in member private seq: number = 0; // A queue for candidates waiting to go out. // We try to amalgamate candidates into a single candidate message where @@ -99,13 +100,14 @@ export class PeerCall implements IDisposable { private _hangupReason?: CallErrorCode; private _remoteMedia: RemoteMedia; private _remoteMuteSettings = new MuteSettings(); - + private flushCandidatesLog?: ILogItem; + constructor( private callId: string, private readonly options: Options, private readonly logItem: ILogItem, ) { - logItem.log({l: "create PeerCall", callId}); + logItem.log({l: "create PeerCall", id: callId}); this._remoteMedia = new RemoteMedia(); this.peerConnection = options.webRTC.createPeerConnection(this.options.forceTURN, this.options.turnServers, 0); @@ -119,12 +121,12 @@ export class PeerCall implements IDisposable { listen("iceconnectionstatechange", () => { const state = this.peerConnection.iceConnectionState; - this.logItem.wrap({l: "onIceConnectionStateChange", status: state}, log => { + logItem.wrap({l: "onIceConnectionStateChange", status: state}, log => { this.onIceConnectionStateChange(state, log); }); }); listen("icecandidate", event => { - this.logItem.wrap("onLocalIceCandidate", log => { + logItem.wrap("onLocalIceCandidate", log => { if (event.candidate) { this.handleLocalIceCandidate(event.candidate, log); } @@ -132,24 +134,24 @@ export class PeerCall implements IDisposable { }); listen("icegatheringstatechange", () => { const state = this.peerConnection.iceGatheringState; - this.logItem.wrap({l: "onIceGatheringStateChange", status: state}, log => { + logItem.wrap({l: "onIceGatheringStateChange", status: state}, log => { this.handleIceGatheringState(state, log); }); }); listen("track", event => { - this.logItem.wrap("onRemoteTrack", log => { + logItem.wrap("onRemoteTrack", log => { this.onRemoteTrack(event.track, event.streams, log); }); }); listen("datachannel", event => { - this.logItem.wrap("onRemoteDataChannel", log => { + logItem.wrap("onRemoteDataChannel", log => { this._dataChannel = event.channel; - this.options.emitUpdate(this, undefined); + this.options.emitUpdate(this, undefined, log); }); }); listen("negotiationneeded", () => { const promiseCreator = () => { - return this.logItem.wrap("onNegotiationNeeded", log => { + return logItem.wrap("onNegotiationNeeded", log => { return this.handleNegotiation(log); }); }; @@ -171,8 +173,8 @@ export class PeerCall implements IDisposable { return this._remoteMuteSettings; } - call(localMedia: LocalMedia, localMuteSettings: MuteSettings): Promise { - return this.logItem.wrap("call", async log => { + call(localMedia: LocalMedia, localMuteSettings: MuteSettings, log: ILogItem): Promise { + return log.wrap("call", async log => { if (this._state !== CallState.Fledgling) { return; } @@ -190,8 +192,8 @@ export class PeerCall implements IDisposable { }); } - answer(localMedia: LocalMedia, localMuteSettings: MuteSettings): Promise { - return this.logItem.wrap("answer", async log => { + answer(localMedia: LocalMedia, localMuteSettings: MuteSettings, log: ILogItem): Promise { + return log.wrap("answer", async log => { if (this._state !== CallState.Ringing) { return; } @@ -226,8 +228,8 @@ export class PeerCall implements IDisposable { }); } - setMedia(localMedia: LocalMedia): Promise { - return this.logItem.wrap("setMedia", async log => { + setMedia(localMedia: LocalMedia, log: ILogItem): Promise { + return log.wrap("setMedia", async log => { log.set("userMedia_audio", !!getStreamAudioTrack(localMedia.userMedia)); log.set("userMedia_video", !!getStreamVideoTrack(localMedia.userMedia)); log.set("screenShare_video", !!getStreamVideoTrack(localMedia.screenShare)); @@ -243,8 +245,8 @@ export class PeerCall implements IDisposable { }); } - setMuted(localMuteSettings: MuteSettings) { - return this.logItem.wrap("setMuted", async log => { + setMuted(localMuteSettings: MuteSettings, log: ILogItem): Promise { + return log.wrap("setMuted", async log => { this.localMuteSettings = localMuteSettings; log.set("cameraMuted", localMuteSettings.camera); log.set("microphoneMuted", localMuteSettings.microphone); @@ -269,8 +271,8 @@ export class PeerCall implements IDisposable { }); } - hangup(errorCode: CallErrorCode): Promise { - return this.logItem.wrap("hangup", log => { + hangup(errorCode: CallErrorCode, log: ILogItem): Promise { + return log.wrap("hangup", log => { return this._hangup(errorCode, log); }); } @@ -299,8 +301,17 @@ export class PeerCall implements IDisposable { await this.sendHangupWithCallId(this.callId, errorCode, log); } - handleIncomingSignallingMessage(message: SignallingMessage, partyId: PartyId): Promise { - return this.logItem.wrap({l: "receive", id: message.type, callId: message.content.call_id, payload: message}, async log => { + handleIncomingSignallingMessage(message: SignallingMessage, partyId: PartyId, log: ILogItem): ILogItem { + // return logItem item immediately so it can be references in sync manner + let logItem; + log.wrap({ + l: "receive signalling message", + type: message.type, + callId: message.content.call_id, + payload: message.content + }, async log => { + logItem = log; + switch (message.type) { case EventType.Invite: if (this.callId !== message.content.call_id) { @@ -332,6 +343,7 @@ export class PeerCall implements IDisposable { break; } }); + return logItem; } private sendHangupWithCallId(callId: string, reason: CallErrorCode | undefined, log: ILogItem): Promise { @@ -436,7 +448,7 @@ export class PeerCall implements IDisposable { } await this.handleInvite(content, partyId, log); // TODO: need to skip state check - await this.answer(this.localMedia!, this.localMuteSettings!); + await this.answer(this.localMedia!, this.localMuteSettings!, log); } else { log.log( "Glare detected: rejecting incoming call " + newCallId + @@ -704,7 +716,7 @@ export class PeerCall implements IDisposable { this.sendCandidateQueue(log); } - private queueCandidate(content: RTCIceCandidate, log: ILogItem): void { + private async queueCandidate(content: RTCIceCandidate, log: ILogItem): Promise { // We partially de-trickle candidates by waiting for `delay` before sending them // amalgamated, in order to avoid sending too many m.call.candidates events and hitting // rate limits in Matrix. @@ -719,29 +731,24 @@ export class PeerCall implements IDisposable { // Don't send the ICE candidates yet if the call is in the ringing state if (this._state === CallState.Ringing) return; + + this.flushCandidatesLog = this.flushCandidatesLog ?? this.logItem.child("flush candidate queue"); + log.refDetached(this.flushCandidatesLog); + const {flushCandidatesLog} = this; // MSC2746 recommends these values (can be quite long when calling because the // callee will need a while to answer the call) - const sendLogItem = this.logItem.child("wait to send candidates"); - log.refDetached(sendLogItem); - this.delay(this.direction === CallDirection.Inbound ? 500 : 2000) - .then(() => { - return this.sendCandidateQueue(sendLogItem); - }, err => {}) // swallow delay AbortError - .finally(() => { - sendLogItem.finish(); - }); + await this.delay(this.direction === CallDirection.Inbound ? 500 : 2000); + this.sendCandidateQueue(flushCandidatesLog); + this.flushCandidatesLog = undefined; } private async sendCandidateQueue(log: ILogItem): Promise { - return log.wrap("send candidates queue", async log => { - log.set("queueLength", this.candidateSendQueue.length); - - if (this.candidateSendQueue.length === 0 || this._state === CallState.Ended) { - return; - } - - const candidates = this.candidateSendQueue; - this.candidateSendQueue = []; + if (this.candidateSendQueue.length === 0 || this._state === CallState.Ended) { + return; + } + const candidates = this.candidateSendQueue; + this.candidateSendQueue = []; + return log.wrap({l: "send candidates", size: candidates.length}, async log => { try { await this.sendSignallingMessage({ type: EventType.Candidates, @@ -753,7 +760,7 @@ export class PeerCall implements IDisposable { }, }, log); // Try to send candidates again just in case we received more candidates while sending. - this.sendCandidateQueue(log); + await this.sendCandidateQueue(log); } catch (error) { log.catch(error); // don't retry this event: we'll send another one later as we might @@ -805,10 +812,11 @@ export class PeerCall implements IDisposable { } } - private onIceConnectionStateChange = (state: RTCIceConnectionState, log: ILogItem): void => { + private onIceConnectionStateChange = async (state: RTCIceConnectionState, log: ILogItem): Promise => { if (this._state === CallState.Ended) { return; // because ICE can still complete as we're ending the call } + let logStats = false; // ideally we'd consider the call to be connected when we get media but // chrome doesn't implement any of the 'onstarted' events yet if (state == 'connected') { @@ -816,15 +824,25 @@ export class PeerCall implements IDisposable { this.iceDisconnectedTimeout = undefined; this.setState(CallState.Connected, log); } else if (state == 'failed') { + logStats = true; this.iceDisconnectedTimeout?.abort(); this.iceDisconnectedTimeout = undefined; this._hangup(CallErrorCode.IceFailed, log); } else if (state == 'disconnected') { + logStats = true; this.iceDisconnectedTimeout = this.options.createTimeout(30 * 1000); this.iceDisconnectedTimeout.elapsed().then(() => { this._hangup(CallErrorCode.IceFailed, log); }, () => { /* ignore AbortError */ }); } + if (logStats) { + const stats = await this.peerConnection.getStats(); + const statsObj = {}; + stats.forEach((value, key) => { + statsObj[key] = value; + }); + log.set("peerConnectionStats", statsObj); + } }; private setState(state: CallState, log: ILogItem): void { @@ -837,7 +855,7 @@ export class PeerCall implements IDisposable { deferred.resolve(); this.statePromiseMap.delete(state); } - this.options.emitUpdate(this, undefined); + this.options.emitUpdate(this, undefined, log); } } @@ -979,7 +997,7 @@ export class PeerCall implements IDisposable { } } } - this.options.emitUpdate(this, undefined); + this.options.emitUpdate(this, undefined, log); }); } @@ -1049,6 +1067,12 @@ export class PeerCall implements IDisposable { this.disposables.dispose(); this.iceDisconnectedTimeout?.abort(); this.peerConnection.close(); + // replace emitUpdate in case any eventhandler in here is still attached + // we really don't want to trigger any code in Member after this + this.options.emitUpdate = (_, __, log) => { + log.log("emitting update from PeerCall after disposal", this.logItem.level.Error); + console.trace("emitting update from PeerCall after disposal"); + }; } public close(reason: CallErrorCode | undefined, log: ILogItem): void { diff --git a/src/matrix/calls/common.ts b/src/matrix/calls/common.ts index 6e3dc7ab..db49a168 100644 --- a/src/matrix/calls/common.ts +++ b/src/matrix/calls/common.ts @@ -35,3 +35,5 @@ export class MuteSettings { return new MuteSettings(!this.microphone, this.camera); } } + +export const CALL_LOG_TYPE = "call"; diff --git a/src/matrix/calls/group/GroupCall.ts b/src/matrix/calls/group/GroupCall.ts index 12d0be51..4f626f7b 100644 --- a/src/matrix/calls/group/GroupCall.ts +++ b/src/matrix/calls/group/GroupCall.ts @@ -17,7 +17,7 @@ limitations under the License. import {ObservableMap} from "../../../observable/map/ObservableMap"; import {Member} from "./Member"; import {LocalMedia} from "../LocalMedia"; -import {MuteSettings} from "../common"; +import {MuteSettings, CALL_LOG_TYPE} from "../common"; import {RoomMember} from "../../room/members/RoomMember"; import {EventEmitter} from "../../../utils/EventEmitter"; import {EventType, CallIntent} from "../callEventTypes"; @@ -30,7 +30,7 @@ import type {Room} from "../../room/Room"; import type {StateEvent} from "../../storage/types"; import type {Platform} from "../../../platform/web/Platform"; import type {EncryptedMessage} from "../../e2ee/olm/Encryption"; -import type {ILogItem} from "../../../logging/types"; +import type {ILogItem, ILogger} from "../../../logging/types"; import type {Storage} from "../../storage/idb/Storage"; export enum GroupCallState { @@ -57,15 +57,29 @@ export type Options = Omit void; encryptDeviceMessage: (roomId: string, userId: string, message: SignallingMessage, log: ILogItem) => Promise, storage: Storage, + logger: ILogger, }; +class JoinedData { + constructor( + public readonly logItem: ILogItem, + public readonly membersLogItem: ILogItem, + public localMedia: LocalMedia, + public localMuteSettings: MuteSettings + ) {} + + dispose() { + this.localMedia.dispose(); + this.logItem.finish(); + } +} + export class GroupCall extends EventEmitter<{change: never}> { private readonly _members: ObservableMap = new ObservableMap(); - private _localMedia?: LocalMedia = undefined; private _memberOptions: MemberOptions; private _state: GroupCallState; - private localMuteSettings: MuteSettings = new MuteSettings(false, false); private bufferedDeviceMessages = new Map>>(); + private joinedData?: JoinedData; constructor( public readonly id: string, @@ -73,11 +87,8 @@ export class GroupCall extends EventEmitter<{change: never}> { private callContent: Record, public readonly roomId: string, private readonly options: Options, - private readonly logItem: ILogItem, ) { super(); - logItem.set("id", this.id); - logItem.set("sessionId", this.options.sessionId); this._state = newCall ? GroupCallState.Fledgling : GroupCallState.Created; this._memberOptions = Object.assign({}, options, { confId: this.id, @@ -88,7 +99,7 @@ export class GroupCall extends EventEmitter<{change: never}> { }); } - get localMedia(): LocalMedia | undefined { return this._localMedia; } + get localMedia(): LocalMedia | undefined { return this.joinedData?.localMedia; } get members(): BaseObservableMap { return this._members; } get isTerminated(): boolean { @@ -107,13 +118,26 @@ export class GroupCall extends EventEmitter<{change: never}> { return this.callContent?.["m.intent"]; } - join(localMedia: LocalMedia): Promise { - return this.logItem.wrap("join", async log => { - if (this._state !== GroupCallState.Created) { - return; - } + async join(localMedia: LocalMedia): Promise { + if (this._state !== GroupCallState.Created || this.joinedData) { + return; + } + const logItem = this.options.logger.child({ + l: "answer call", + t: CALL_LOG_TYPE, + id: this.id, + ownSessionId: this.options.sessionId + }); + const membersLogItem = logItem.child("member connections"); + const joinedData = new JoinedData( + logItem, + membersLogItem, + localMedia, + new MuteSettings() + ); + this.joinedData = joinedData; + await joinedData.logItem.wrap("join", async log => { this._state = GroupCallState.Joining; - this._localMedia = localMedia; this.emitChange(); const memberContent = await this._createJoinPayload(); // send m.call.member state event @@ -122,15 +146,15 @@ export class GroupCall extends EventEmitter<{change: never}> { this.emitChange(); // send invite to all members that are < my userId for (const [,member] of this._members) { - member.connect(this._localMedia!.clone(), this.localMuteSettings); + this.connectToMember(member, joinedData, log); } }); } async setMedia(localMedia: LocalMedia): Promise { - if (this._state === GroupCallState.Joining || this._state === GroupCallState.Joined && this._localMedia) { - const oldMedia = this._localMedia!; - this._localMedia = localMedia; + if ((this._state === GroupCallState.Joining || this._state === GroupCallState.Joined) && this.joinedData) { + const oldMedia = this.joinedData.localMedia; + this.joinedData.localMedia = localMedia; await Promise.all(Array.from(this._members.values()).map(m => { return m.setMedia(localMedia, oldMedia); })); @@ -138,43 +162,53 @@ export class GroupCall extends EventEmitter<{change: never}> { } } - setMuted(muteSettings: MuteSettings) { - this.localMuteSettings = muteSettings; - if (this._state === GroupCallState.Joining || this._state === GroupCallState.Joined) { - for (const [,member] of this._members) { - member.setMuted(this.localMuteSettings); - } + async setMuted(muteSettings: MuteSettings): Promise { + const {joinedData} = this; + if (!joinedData) { + return; } + joinedData.localMuteSettings = muteSettings; + await Promise.all(Array.from(this._members.values()).map(m => { + return m.setMuted(joinedData.localMuteSettings); + })); this.emitChange(); } - get muteSettings(): MuteSettings { - return this.localMuteSettings; + get muteSettings(): MuteSettings | undefined { + return this.joinedData?.localMuteSettings; } get hasJoined() { return this._state === GroupCallState.Joining || this._state === GroupCallState.Joined; } - leave(): Promise { - return this.logItem.wrap("leave", async log => { - const memberContent = await this._leaveCallMemberContent(); - // send m.call.member state event - if (memberContent) { - const request = this.options.hsApi.sendState(this.roomId, EventType.GroupCallMember, this.options.ownUserId, memberContent, {log}); - await request.response(); - // our own user isn't included in members, so not in the count - if (this.intent === CallIntent.Ring && this._members.size === 0) { - await this.terminate(); + async leave(): Promise { + const {joinedData} = this; + if (!joinedData) { + return; + } + await joinedData.logItem.wrap("leave", async log => { + try { + const memberContent = await this._leaveCallMemberContent(); + // send m.call.member state event + if (memberContent) { + const request = this.options.hsApi.sendState(this.roomId, EventType.GroupCallMember, this.options.ownUserId, memberContent, {log}); + await request.response(); + // our own user isn't included in members, so not in the count + if (this.intent === CallIntent.Ring && this._members.size === 0) { + await this.terminate(log); + } + } else { + log.set("already_left", true); } - } else { - log.set("already_left", true); + } finally { + this.disconnect(log); } }); } - terminate(): Promise { - return this.logItem.wrap("terminate", async log => { + terminate(log?: ILogItem): Promise { + return this.options.logger.wrapOrRun(log, {l: "terminate call", t: CALL_LOG_TYPE}, async log => { if (this._state === GroupCallState.Fledgling) { return; } @@ -186,8 +220,8 @@ export class GroupCall extends EventEmitter<{change: never}> { } /** @internal */ - create(type: "m.video" | "m.voice"): Promise { - return this.logItem.wrap("create", async log => { + create(type: "m.video" | "m.voice", log?: ILogItem): Promise { + return this.options.logger.wrapOrRun(log, {l: "create call", t: CALL_LOG_TYPE}, async log => { if (this._state !== GroupCallState.Fledgling) { return; } @@ -205,8 +239,8 @@ export class GroupCall extends EventEmitter<{change: never}> { /** @internal */ updateCallEvent(callContent: Record, syncLog: ILogItem) { - this.logItem.wrap("updateCallEvent", log => { - syncLog.refDetached(log); + syncLog.wrap({l: "update call", t: CALL_LOG_TYPE}, log => { + log.set("id", this.id); this.callContent = callContent; if (this._state === GroupCallState.Creating) { this._state = GroupCallState.Created; @@ -218,14 +252,13 @@ export class GroupCall extends EventEmitter<{change: never}> { /** @internal */ updateMembership(userId: string, callMembership: CallMembership, syncLog: ILogItem) { - this.logItem.wrap({l: "updateMember", id: userId}, log => { - syncLog.refDetached(log); + syncLog.wrap({l: "update call membership", t: CALL_LOG_TYPE, id: this.id, userId}, log => { const devices = callMembership["m.devices"]; const previousDeviceIds = this.getDeviceIdsForUserId(userId); for (const device of devices) { const deviceId = device.device_id; const memberKey = getMemberKey(userId, deviceId); - log.wrap({l: "update device member", id: memberKey, sessionId: device.session_id}, log => { + log.wrap({l: "update device membership", id: memberKey, sessionId: device.session_id}, log => { if (userId === this.options.ownUserId && deviceId === this.options.ownDeviceId) { if (this._state === GroupCallState.Joining) { log.set("update_own", true); @@ -241,27 +274,23 @@ export class GroupCall extends EventEmitter<{change: never}> { } else { if (member && sessionIdChanged) { log.set("removedSessionId", member.sessionId); - member.disconnect(false); - member.dispose(); + member.disconnect(false, log); this._members.remove(memberKey); - member = undefined; + member = undefined; } - const logItem = this.logItem.child({l: "member", id: memberKey}); log.set("add", true); - log.refDetached(logItem); member = new Member( RoomMember.fromUserId(this.roomId, userId, "join"), - device, this._memberOptions, logItem + device, this._memberOptions, ); this._members.add(memberKey, member); - if (this._state === GroupCallState.Joining || this._state === GroupCallState.Joined) { - // Safari can't send a MediaStream to multiple sources, so clone it - member.connect(this._localMedia!.clone(), this.localMuteSettings); + if (this.joinedData) { + this.connectToMember(member, this.joinedData, log); } } // flush pending messages, either after having created the member, // or updated the session id with updateCallInfo - this.flushPendingDeviceMessages(member, log); + this.flushPendingIncomingDeviceMessages(member, log); } }); } @@ -284,8 +313,11 @@ export class GroupCall extends EventEmitter<{change: never}> { /** @internal */ removeMembership(userId: string, syncLog: ILogItem) { const deviceIds = this.getDeviceIdsForUserId(userId); - this.logItem.wrap("removeMember", log => { - syncLog.refDetached(log); + syncLog.wrap({ + l: "remove call member", + t: CALL_LOG_TYPE, + id: this.id + }, log => { for (const deviceId of deviceIds) { this.removeMemberDevice(userId, deviceId, log); } @@ -295,7 +327,7 @@ export class GroupCall extends EventEmitter<{change: never}> { }); } - private flushPendingDeviceMessages(member: Member, log: ILogItem) { + private flushPendingIncomingDeviceMessages(member: Member, log: ILogItem) { const memberKey = getMemberKey(member.userId, member.deviceId); const bufferedMessages = this.bufferedDeviceMessages.get(memberKey); // check if we have any pending message for the member with (userid, deviceid, sessionid) @@ -323,16 +355,21 @@ export class GroupCall extends EventEmitter<{change: never}> { } private removeOwnDevice(log: ILogItem) { + log.set("leave_own", true); + this.disconnect(log); + } + + /** @internal */ + disconnect(log: ILogItem) { if (this._state === GroupCallState.Joined) { - log.set("leave_own", true); for (const [,member] of this._members) { - member.disconnect(true); + member.disconnect(true, log); } - this._localMedia?.dispose(); - this._localMedia = undefined; this._state = GroupCallState.Created; - this.emitChange(); } + this.joinedData?.dispose(); + this.joinedData = undefined; + this.emitChange(); } /** @internal */ @@ -343,7 +380,7 @@ export class GroupCall extends EventEmitter<{change: never}> { if (member) { log.set("leave", true); this._members.remove(memberKey); - member.disconnect(false); + member.disconnect(false, log); } this.emitChange(); } @@ -356,8 +393,10 @@ export class GroupCall extends EventEmitter<{change: never}> { if (member && message.content.sender_session_id === member.sessionId) { member.handleDeviceMessage(message, syncLog); } else { - const item = this.logItem.log({ - l: "buffering to_device message, member not found", + const item = syncLog.log({ + l: "call: buffering to_device message, member not found", + t: CALL_LOG_TYPE, + id: this.id, userId, deviceId, sessionId: message.content.sender_session_id, @@ -375,11 +414,6 @@ export class GroupCall extends EventEmitter<{change: never}> { } } - /** @internal */ - dispose() { - this.logItem.finish(); - } - private async _createJoinPayload() { const {storage} = this.options; const txn = await storage.readTxn([storage.storeNames.roomState]); @@ -424,6 +458,14 @@ export class GroupCall extends EventEmitter<{change: never}> { } } + private connectToMember(member: Member, joinedData: JoinedData, log: ILogItem) { + const logItem = joinedData.membersLogItem.child({l: "member", id: getMemberKey(member.userId, member.deviceId)}); + logItem.set("sessionId", member.sessionId); + log.refDetached(logItem); + // Safari can't send a MediaStream to multiple sources, so clone it + member.connect(joinedData.localMedia.clone(), joinedData.localMuteSettings, logItem); + } + protected emitChange() { this.emit("change"); this.options.emitUpdate(this); diff --git a/src/matrix/calls/group/Member.ts b/src/matrix/calls/group/Member.ts index bed1af94..5ddee0fb 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -49,31 +49,37 @@ const errorCodesWithoutRetry = [ CallErrorCode.NewSession ]; +/** @internal */ +class MemberConnection { + public retryCount: number = 0; + public peerCall?: PeerCall; + + constructor( + public localMedia: LocalMedia, + public localMuteSettings: MuteSettings, + public readonly logItem: ILogItem + ) {} +} + export class Member { - private peerCall?: PeerCall; - private localMedia?: LocalMedia; - private localMuteSettings?: MuteSettings; - private retryCount: number = 0; + private connection?: MemberConnection; constructor( public readonly member: RoomMember, private callDeviceMembership: CallDeviceMembership, private readonly options: Options, - private readonly logItem: ILogItem, - ) { - this.logItem.set("sessionId", this.sessionId); - } + ) {} get remoteMedia(): RemoteMedia | undefined { - return this.peerCall?.remoteMedia; + return this.connection?.peerCall?.remoteMedia; } get remoteMuteSettings(): MuteSettings | undefined { - return this.peerCall?.remoteMuteSettings; + return this.connection?.peerCall?.remoteMuteSettings; } get isConnected(): boolean { - return this.peerCall?.state === CallState.Connected; + return this.connection?.peerCall?.state === CallState.Connected; } get userId(): string { @@ -90,14 +96,23 @@ export class Member { } get dataChannel(): any | undefined { - return this.peerCall?.dataChannel; + return this.connection?.peerCall?.dataChannel; } /** @internal */ - connect(localMedia: LocalMedia, localMuteSettings: MuteSettings) { - this.logItem.wrap("connect", () => { - this.localMedia = localMedia; - this.localMuteSettings = localMuteSettings; + connect(localMedia: LocalMedia, localMuteSettings: MuteSettings, memberLogItem: ILogItem) { + if (this.connection) { + return; + } + const connection = new MemberConnection(localMedia, localMuteSettings, memberLogItem); + this.connection = connection; + connection.logItem.wrap("connect", async log => { + await this.callIfNeeded(log); + }); + } + + private callIfNeeded(log: ILogItem): Promise { + return log.wrap("callIfNeeded", async log => { // otherwise wait for it to connect let shouldInitiateCall; // the lexicographically lower side initiates the call @@ -107,58 +122,71 @@ export class Member { shouldInitiateCall = this.member.userId > this.options.ownUserId; } if (shouldInitiateCall) { - this.peerCall = this._createPeerCall(makeId("c")); - this.peerCall.call(localMedia, localMuteSettings); - } - }); - } - - /** @internal */ - disconnect(hangup: boolean) { - this.logItem.wrap("disconnect", log => { - if (hangup) { - this.peerCall?.hangup(CallErrorCode.UserHangup); + const connection = this.connection!; + connection.peerCall = this._createPeerCall(makeId("c")); + await connection.peerCall.call( + connection.localMedia, + connection.localMuteSettings, + log + ); } else { - this.peerCall?.close(undefined, log); + log.set("wait_for_invite", true); } - this.peerCall?.dispose(); - this.peerCall = undefined; - this.localMedia?.dispose(); - this.localMedia = undefined; - this.localMuteSettings = undefined; - this.retryCount = 0; - }); - } - - dispose() { - this.logItem.finish(); - } - - /** @internal */ - updateCallInfo(callDeviceMembership: CallDeviceMembership, log: ILogItem) { - log.wrap({l: "updateing device membership", deviceId: this.deviceId}, log => { - this.callDeviceMembership = callDeviceMembership; }); } /** @internal */ - emitUpdate = (peerCall: PeerCall, params: any) => { - // these must be set as the update comes from the peerCall, - // which only exists when these are set - const localMedia = this.localMedia!; - const localMuteSettings = this.localMuteSettings!; + disconnect(hangup: boolean, causeItem: ILogItem) { + const {connection} = this; + if (!connection) { + return; + } + connection.logItem.wrap("disconnect", async log => { + log.refDetached(causeItem); + if (hangup) { + connection.peerCall?.hangup(CallErrorCode.UserHangup, log); + } else { + await connection.peerCall?.close(undefined, log); + } + connection.peerCall?.dispose(); + connection.localMedia?.dispose(); + this.connection = undefined; + }); + connection.logItem.finish(); + } + + /** @internal */ + updateCallInfo(callDeviceMembership: CallDeviceMembership, causeItem: ILogItem) { + this.callDeviceMembership = callDeviceMembership; + if (this.connection) { + this.connection.logItem.refDetached(causeItem); + } + } + + /** @internal */ + emitUpdateFromPeerCall = (peerCall: PeerCall, params: any, log: ILogItem): void => { + const connection = this.connection!; if (peerCall.state === CallState.Ringing) { - peerCall.answer(localMedia, localMuteSettings); + connection.logItem.wrap("ringing, answer peercall", answerLog => { + log.refDetached(answerLog); + return peerCall.answer(connection.localMedia, connection.localMuteSettings, answerLog); + }); } else if (peerCall.state === CallState.Ended) { const hangupReason = peerCall.hangupReason; peerCall.dispose(); - this.peerCall = undefined; + connection.peerCall = undefined; if (hangupReason && !errorCodesWithoutRetry.includes(hangupReason)) { - this.retryCount += 1; - if (this.retryCount <= 3) { - this.connect(localMedia, localMuteSettings); - } + connection.retryCount += 1; + const {retryCount} = connection; + connection.logItem.wrap({l: "retry connection", retryCount}, async retryLog => { + log.refDetached(retryLog); + if (retryCount <= 3) { + await this.callIfNeeded(retryLog); + } else { + this.disconnect(false, retryLog); + } + }); } } this.options.emitUpdate(this, params); @@ -194,38 +222,50 @@ export class Member { } /** @internal */ - handleDeviceMessage(message: SignallingMessage, syncLog: ILogItem): void { - syncLog.refDetached(this.logItem); - const destSessionId = message.content.dest_session_id; - if (destSessionId !== this.options.sessionId) { - this.logItem.log({l: "ignoring to_device event with wrong session_id", destSessionId, type: message.type}); - return; - } - if (message.type === EventType.Invite && !this.peerCall) { - this.peerCall = this._createPeerCall(message.content.call_id); - } - if (this.peerCall) { - this.peerCall.handleIncomingSignallingMessage(message, this.deviceId); + handleDeviceMessage(message: SignallingMessage, syncLog: ILogItem): void{ + const {connection} = this; + if (connection) { + const destSessionId = message.content.dest_session_id; + if (destSessionId !== this.options.sessionId) { + const logItem = connection.logItem.log({l: "ignoring to_device event with wrong session_id", destSessionId, type: message.type}); + syncLog.refDetached(logItem); + return; + } + if (message.type === EventType.Invite && !connection.peerCall) { + connection.peerCall = this._createPeerCall(message.content.call_id); + } + if (connection.peerCall) { + const item = connection.peerCall.handleIncomingSignallingMessage(message, this.deviceId, connection.logItem); + syncLog.refDetached(item); + } else { + // TODO: need to buffer events until invite comes? + } } else { - // TODO: need to buffer events until invite comes? + syncLog.log({l: "member not connected", userId: this.userId, deviceId: this.deviceId}); } } /** @internal */ async setMedia(localMedia: LocalMedia, previousMedia: LocalMedia): Promise { - this.localMedia = localMedia.replaceClone(this.localMedia, previousMedia); - await this.peerCall?.setMedia(this.localMedia); + const {connection} = this; + if (connection) { + connection.localMedia = connection.localMedia.replaceClone(connection.localMedia, previousMedia); + await connection.peerCall?.setMedia(connection.localMedia, connection.logItem); + } } - setMuted(muteSettings: MuteSettings) { - this.localMuteSettings = muteSettings; - this.peerCall?.setMuted(muteSettings); + async setMuted(muteSettings: MuteSettings): Promise { + const {connection} = this; + if (connection) { + connection.localMuteSettings = muteSettings; + await connection.peerCall?.setMuted(muteSettings, connection.logItem); + } } private _createPeerCall(callId: string): PeerCall { return new PeerCall(callId, Object.assign({}, this.options, { - emitUpdate: this.emitUpdate, + emitUpdate: this.emitUpdateFromPeerCall, sendSignallingMessage: this.sendSignallingMessage - }), this.logItem); + }), this.connection!.logItem); } } diff --git a/src/platform/types/WebRTC.ts b/src/platform/types/WebRTC.ts index 9f2e1e0e..39ad49c5 100644 --- a/src/platform/types/WebRTC.ts +++ b/src/platform/types/WebRTC.ts @@ -147,6 +147,13 @@ export interface PeerConnection { setRemoteDescription(description: SessionDescriptionInit): Promise; addEventListener(type: K, listener: (this: PeerConnection, ev: PeerConnectionEventMap[K]) => any, options?: boolean | AddEventListenerOptions): void; removeEventListener(type: K, listener: (this: PeerConnection, ev: PeerConnectionEventMap[K]) => any, options?: boolean | EventListenerOptions): void; + getStats(selector?: Track | null): Promise; +} + + + +interface StatsReport { + forEach(callbackfn: (value: any, key: string, parent: StatsReport) => void, thisArg?: any): void; } export interface Receiver {