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 d1634320..7470cf15 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 e5e70a46..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,12 +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", id: callId}); this._remoteMedia = new RemoteMedia(); this.peerConnection = options.webRTC.createPeerConnection(this.options.forceTURN, this.options.turnServers, 0); @@ -118,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); } @@ -131,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); }); }; @@ -170,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; } @@ -189,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; } @@ -225,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)); @@ -242,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); @@ -268,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); }); } @@ -298,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, partyId}, 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) { @@ -323,6 +335,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: @@ -330,6 +343,7 @@ export class PeerCall implements IDisposable { break; } }); + return logItem; } private sendHangupWithCallId(callId: string, reason: CallErrorCode | undefined, log: ILogItem): Promise { @@ -434,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 + @@ -702,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. @@ -717,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, @@ -751,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 @@ -803,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') { @@ -814,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 { @@ -835,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); } } @@ -977,7 +997,7 @@ export class PeerCall implements IDisposable { } } } - this.options.emitUpdate(this, undefined); + this.options.emitUpdate(this, undefined, log); }); } @@ -1045,7 +1065,14 @@ export class PeerCall implements IDisposable { public dispose(): void { 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/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) 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 55efa6f9..45f349b4 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; private _deviceIndex?: number; private _eventTimestamp?: number; @@ -76,10 +90,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); this._state = newCall ? GroupCallState.Fledgling : GroupCallState.Created; this._memberOptions = Object.assign({}, options, { confId: this.id, @@ -90,7 +102,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 { @@ -117,13 +129,26 @@ export class GroupCall extends EventEmitter<{change: never}> { return this._eventTimestamp; } - 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 @@ -132,15 +157,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); })); @@ -148,43 +173,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; } @@ -196,8 +231,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; } @@ -215,8 +250,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; @@ -228,15 +263,14 @@ export class GroupCall extends EventEmitter<{change: never}> { /** @internal */ updateMembership(userId: string, callMembership: CallMembership, eventTimestamp: number, 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 (let deviceIndex = 0; deviceIndex < devices.length; deviceIndex++) { const device = devices[deviceIndex]; 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) { this._deviceIndex = deviceIndex; @@ -249,26 +283,30 @@ 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, deviceIndex, eventTimestamp, log); + member.updateCallInfo(device, deviceIndex, eventTimestamp, log); } else { - const logItem = this.logItem.child({l: "member", id: memberKey}); + if (member && sessionIdChanged) { + log.set("removedSessionId", member.sessionId); + member.disconnect(false, log); + this._members.remove(memberKey); + member = undefined; + } log.set("add", true); - log.refDetached(logItem); member = new Member( RoomMember.fromUserId(this.roomId, userId, "join"), - device, deviceIndex, eventTimestamp, this._memberOptions, logItem + device, deviceIndex, eventTimestamp, 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); } }); } @@ -291,8 +329,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); } @@ -302,7 +343,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) @@ -330,30 +371,34 @@ 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 */ 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, log); + } + this.emitChange(); } /** @internal */ @@ -364,8 +409,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, @@ -383,11 +430,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]); @@ -436,6 +478,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 72a6ee55..a22725dd 100644 --- a/src/matrix/calls/group/Member.ts +++ b/src/matrix/calls/group/Member.ts @@ -49,11 +49,20 @@ 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, @@ -61,19 +70,18 @@ export class Member { private _deviceIndex: number, private _eventTimestamp: number, private readonly options: Options, - private readonly logItem: ILogItem, ) {} 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,7 +98,7 @@ export class Member { } get dataChannel(): any | undefined { - return this.peerCall?.dataChannel; + return this.connection?.peerCall?.dataChannel; } get deviceIndex(): number { @@ -102,10 +110,19 @@ export class Member { } /** @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 @@ -115,69 +132,79 @@ 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.retryCount = 0; }); } /** @internal */ - updateCallInfo(callDeviceMembership: CallDeviceMembership, deviceIndex: number, eventTimestamp: number, 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) { - log.wrap({ - l: "member event changes session id", - oldSessionId: this.sessionId, - newSessionId: callDeviceMembership.session_id - }, 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; - this.disconnect(false); - // connect again, as the other side might be waiting for our invite - // after refreshing - this.connect(localMedia!, 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); } - this.callDeviceMembership = callDeviceMembership; - this._deviceIndex = deviceIndex; - this._eventTimestamp = eventTimestamp; + connection.peerCall?.dispose(); + connection.localMedia?.dispose(); + this.connection = undefined; }); + connection.logItem.finish(); } /** @internal */ - emitUpdate = (peerCall: PeerCall, params: any) => { + updateCallInfo( + callDeviceMembership: CallDeviceMembership, + deviceIndex: number, + eventTimestamp: number, + causeItem: ILogItem + ) { + this.callDeviceMembership = callDeviceMembership; + this._deviceIndex = deviceIndex; + this._eventTimestamp = eventTimestamp; + + 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(this.localMedia!, this.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(this.localMedia!, this.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); @@ -213,38 +240,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 {