improve logging of arrival of to_device call signalling messages

This commit is contained in:
Bruno Windels 2023-02-07 19:42:20 +01:00
parent ddb5865ccb
commit 7f9d64c972

View File

@ -343,64 +343,65 @@ export class Member {
/** @internal */ /** @internal */
handleDeviceMessage(message: SignallingMessage<MGroupCallBase>, syncLog: ILogItem): void { handleDeviceMessage(message: SignallingMessage<MGroupCallBase>, syncLog: ILogItem): void {
this.errorBoundary.try(() => { this.errorBoundary.try(() => {
const {connection} = this; syncLog.wrap({l: "Member.handleDeviceMessage", type: message.type, seq: message.content?.seq}, log => {
if (connection) { const {connection} = this;
const destSessionId = message.content.dest_session_id; if (connection) {
if (destSessionId !== this.options.sessionId) { const destSessionId = message.content.dest_session_id;
const logItem = connection.logItem.log({l: "ignoring to_device event with wrong session_id", destSessionId, type: message.type}); if (destSessionId !== this.options.sessionId) {
syncLog.refDetached(logItem); const logItem = connection.logItem.log({l: "ignoring to_device event with wrong session_id", destSessionId, type: message.type});
return; log.refDetached(logItem);
} return;
// if there is no peerCall, we either create it with an invite and Handle is implied or we'll ignore it }
let action = IncomingMessageAction.Handle; // if there is no peerCall, we either create it with an invite and Handle is implied or we'll ignore it
if (connection.peerCall) { if (connection.peerCall) {
action = connection.peerCall.getMessageAction(message); const action = connection.peerCall.getMessageAction(message);
// deal with glare and replacing the call before creating new calls // deal with glare and replacing the call before creating new calls
if (action === IncomingMessageAction.InviteGlare) { if (action === IncomingMessageAction.InviteGlare) {
const {shouldReplace, log} = connection.peerCall.handleInviteGlare(message, this.deviceId, connection.logItem); const {shouldReplace, log} = connection.peerCall.handleInviteGlare(message, this.deviceId, connection.logItem);
if (log) { if (log) {
syncLog.refDetached(log); log.refDetached(log);
} }
if (shouldReplace) { if (shouldReplace) {
connection.peerCall.dispose(); connection.peerCall.dispose();
connection.peerCall = undefined; connection.peerCall = undefined;
action = IncomingMessageAction.Handle; }
} }
} }
} // create call on invite
if (message.type === EventType.Invite && !connection.peerCall) { if (message.type === EventType.Invite && !connection.peerCall) {
connection.peerCall = this._createPeerCall(message.content.call_id); connection.peerCall = this._createPeerCall(message.content.call_id);
} }
if (action === IncomingMessageAction.Handle) { // enqueue
const idx = sortedIndex(connection.queuedSignallingMessages, message, (a, b) => a.content.seq - b.content.seq); const idx = sortedIndex(connection.queuedSignallingMessages, message, (a, b) => a.content.seq - b.content.seq);
connection.queuedSignallingMessages.splice(idx, 0, message); connection.queuedSignallingMessages.splice(idx, 0, message);
// dequeue as much as we can
let hasNewMessageBeenDequeued = false;
if (connection.peerCall) { if (connection.peerCall) {
const hasNewMessageBeenDequeued = this.dequeueSignallingMessages(connection, connection.peerCall, message, syncLog); hasNewMessageBeenDequeued = this.dequeueSignallingMessages(connection, connection.peerCall, message, log);
if (!hasNewMessageBeenDequeued) {
syncLog.refDetached(connection.logItem.log({l: "queued signalling message", type: message.type, seq: message.content.seq}));
}
} }
} else if (action === IncomingMessageAction.Ignore && connection.peerCall) { if (!hasNewMessageBeenDequeued) {
const logItem = connection.logItem.log({l: "ignoring to_device event with wrong call_id", callId: message.content.call_id, type: message.type}); log.refDetached(connection.logItem.log({l: "queued message", type: message.type, seq: message.content.seq, idx}));
syncLog.refDetached(logItem); }
} else {
// TODO: the right thing to do here would be to at least enqueue the message rather than drop it,
// and if it's up to the other end to send the invite and the type is an invite to actually
// call connect and assume the m.call.member state update is on its way?
syncLog.log({l: "member not connected", userId: this.userId, deviceId: this.deviceId});
} }
} else { });
syncLog.log({l: "member not connected", userId: this.userId, deviceId: this.deviceId});
}
}); });
} }
private dequeueSignallingMessages(connection: MemberConnection, peerCall: PeerCall, newMessage: SignallingMessage<MGroupCallBase>, syncLog: ILogItem): boolean { private dequeueSignallingMessages(connection: MemberConnection, peerCall: PeerCall, newMessage: SignallingMessage<MGroupCallBase>, syncLog: ILogItem): boolean {
let hasNewMessageBeenDequeued = false; let hasNewMessageBeenDequeued = false;
while (connection.canDequeueNextSignallingMessage) { while (connection.canDequeueNextSignallingMessage) {
syncLog.wrap("dequeue message", log => { const message = connection.queuedSignallingMessages.shift()!;
const message = connection.queuedSignallingMessages.shift()!; const isNewMsg = message === newMessage;
if (message === newMessage) { hasNewMessageBeenDequeued = hasNewMessageBeenDequeued || isNewMsg;
log.set("isNewMsg", true); syncLog.wrap(isNewMsg ? "process message" : "dequeue message", log => {
hasNewMessageBeenDequeued = true;
}
const seq = message.content?.seq; const seq = message.content?.seq;
log.set("seq", seq); log.set("seq", seq);
log.set("type", message.type);
// ignore items in the queue that should not be handled and prevent // ignore items in the queue that should not be handled and prevent
// the lastProcessedSeqNr being corrupted with the `seq` for other call ids // the lastProcessedSeqNr being corrupted with the `seq` for other call ids
// XXX: Not needed anymore when seq is scoped to call_id // XXX: Not needed anymore when seq is scoped to call_id
@ -411,7 +412,6 @@ export class Member {
log.refDetached(item); log.refDetached(item);
connection.lastProcessedSeqNr = seq; connection.lastProcessedSeqNr = seq;
} else { } else {
log.set("type", message.type);
log.set("ignored", true); log.set("ignored", true);
connection.lastIgnoredSeqNr = seq; connection.lastIgnoredSeqNr = seq;
} }