logging improvements

This commit is contained in:
Bruno Windels 2022-05-04 18:44:11 +02:00
parent 1a0b11ff7e
commit 1a08616df1
12 changed files with 359 additions and 220 deletions

View File

@ -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;
}
</style>
</head>
<body>
<nav>
<button id="openFile">Open log file</button>
<button id="collapseAll">Collapse all</button>
<button id="hideCollapsed">Hide collapsed root items</button>
<button id="hideHighlightedSiblings" title="Hide collapsed siblings of highlighted">Hide non-highlighted</button>
<button id="showAll">Show all</button>
<form id="highlightForm">
<input type="text" id="highlight" name="highlight" placeholder="Highlight a search term" autocomplete="on">
<output id="highlightMatches"></output>
</form>
<div>
<button id="openFile">Open log file</button>
<button id="collapseAll">Collapse all</button>
<button id="hideCollapsed">Hide collapsed root items</button>
<button id="hideHighlightedSiblings" title="Hide collapsed siblings of highlighted">Hide non-highlighted</button>
<button id="showAll">Show all</button>
<form id="highlightForm">
<input type="text" id="highlight" name="highlight" placeholder="Highlight a search term" autocomplete="on">
<output id="highlightMatches"></output>
</form>
</div>
<h2 id="filename"></h2>
</nav>
<main></main>
<aside></aside>

View File

@ -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) {

View File

@ -68,7 +68,9 @@ export class CallViewModel extends ViewModel<Options> {
}
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<OwnMemberOptions> 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 {

View File

@ -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") {

View File

@ -65,12 +65,18 @@ export class NullLogItem implements ILogItem {
}
wrap<T>(_: LabelOrValues, callback: LogCallback<T>): T {
return this.run(callback);
}
run<T>(callback: LogCallback<T>): T {
return callback(this);
}
log(): ILogItem {
return this;
}
set(): ILogItem { return this; }
runDetached(_: LabelOrValues, callback: LogCallback<unknown>): ILogItem {

View File

@ -42,6 +42,8 @@ export interface ILogItem {
readonly start?: number;
readonly values: LogItemValues;
wrap<T>(labelOrValues: LabelOrValues, callback: LogCallback<T>, 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<T>(callback: LogCallback<T>): T;
log(labelOrValues: LabelOrValues, logLevel?: LogLevel): ILogItem;
set(key: string | object, value: unknown): ILogItem;
runDetached(labelOrValues: LabelOrValues, callback: LogCallback<unknown>, logLevel?: LogLevel, filterCreator?: FilterCreator): ILogItem;

View File

@ -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<GroupCallOptions, "emitUpdate" | "createTimeout"> & {
logger: ILogger,
clock: Clock
};
@ -78,7 +78,7 @@ export class CallHandler {
}
private async _loadCallEntries(callEntries: CallEntry[], txn: Transaction): Promise<void> {
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<GroupCall> {
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,

View File

@ -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<MCallBase>, log: ILogItem) => Promise<void>;
};
@ -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<void> {
return this.logItem.wrap("call", async log => {
call(localMedia: LocalMedia, localMuteSettings: MuteSettings, log: ILogItem): Promise<void> {
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<void> {
return this.logItem.wrap("answer", async log => {
answer(localMedia: LocalMedia, localMuteSettings: MuteSettings, log: ILogItem): Promise<void> {
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<void> {
return this.logItem.wrap("setMedia", async log => {
setMedia(localMedia: LocalMedia, log: ILogItem): Promise<void> {
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<void> {
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<void> {
return this.logItem.wrap("hangup", log => {
hangup(errorCode: CallErrorCode, log: ILogItem): Promise<void> {
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<B extends MCallBase>(message: SignallingMessage<B>, partyId: PartyId): Promise<void> {
return this.logItem.wrap({l: "receive", id: message.type, callId: message.content.call_id, payload: message}, async log => {
handleIncomingSignallingMessage<B extends MCallBase>(message: SignallingMessage<B>, 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<void> {
@ -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<void> {
// 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<void> {
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<void> => {
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 {

View File

@ -35,3 +35,5 @@ export class MuteSettings {
return new MuteSettings(!this.microphone, this.camera);
}
}
export const CALL_LOG_TYPE = "call";

View File

@ -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<MemberOptions, "emitUpdate" | "confId" | "encryptDevi
emitUpdate: (call: GroupCall, params?: any) => void;
encryptDeviceMessage: (roomId: string, userId: string, message: SignallingMessage<MGroupCallBase>, log: ILogItem) => Promise<EncryptedMessage>,
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<string, Member> = new ObservableMap();
private _localMedia?: LocalMedia = undefined;
private _memberOptions: MemberOptions;
private _state: GroupCallState;
private localMuteSettings: MuteSettings = new MuteSettings(false, false);
private bufferedDeviceMessages = new Map<string, Set<SignallingMessage<MGroupCallBase>>>();
private joinedData?: JoinedData;
constructor(
public readonly id: string,
@ -73,11 +87,8 @@ export class GroupCall extends EventEmitter<{change: never}> {
private callContent: Record<string, any>,
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<string, Member> { 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<void> {
return this.logItem.wrap("join", async log => {
if (this._state !== GroupCallState.Created) {
return;
}
async join(localMedia: LocalMedia): Promise<void> {
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<void> {
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<void> {
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<void> {
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<void> {
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<void> {
return this.logItem.wrap("terminate", async log => {
terminate(log?: ILogItem): Promise<void> {
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<void> {
return this.logItem.wrap("create", async log => {
create(type: "m.video" | "m.voice", log?: ILogItem): Promise<void> {
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<string, any>, 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);

View File

@ -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<void> {
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<MGroupCallBase>, 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<MGroupCallBase>, 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<void> {
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<void> {
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);
}
}

View File

@ -147,6 +147,13 @@ export interface PeerConnection {
setRemoteDescription(description: SessionDescriptionInit): Promise<void>;
addEventListener<K extends keyof PeerConnectionEventMap>(type: K, listener: (this: PeerConnection, ev: PeerConnectionEventMap[K]) => any, options?: boolean | AddEventListenerOptions): void;
removeEventListener<K extends keyof PeerConnectionEventMap>(type: K, listener: (this: PeerConnection, ev: PeerConnectionEventMap[K]) => any, options?: boolean | EventListenerOptions): void;
getStats(selector?: Track | null): Promise<StatsReport>;
}
interface StatsReport {
forEach(callbackfn: (value: any, key: string, parent: StatsReport) => void, thisArg?: any): void;
}
export interface Receiver {