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] 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 {