diff --git a/ts/services/calling.ts b/ts/services/calling.ts index 68ce51e54..08c385677 100644 --- a/ts/services/calling.ts +++ b/ts/services/calling.ts @@ -197,6 +197,7 @@ type CallingReduxInterface = Pick< | 'callStateChange' | 'cancelIncomingGroupCallRing' | 'cancelPresenting' + | 'declineCall' | 'directCallAudioLevelsChange' | 'groupCallAudioLevelsChange' | 'groupCallEnded' @@ -351,6 +352,46 @@ async function ensureSystemPermissions({ } } +function getLogId( + options: + | { + source: string; + additional?: string; + conversationId: string | undefined; + } + | { + source: string; + additional?: string; + conversation: ConversationModel | undefined; + } + | { + source: string; + additional?: string; + conversationType: ConversationType | undefined; + } +): string { + const { source, additional } = options; + let idForLogging: string; + + if ('conversationId' in options) { + idForLogging = + window.ConversationController.get( + options.conversationId + )?.idForLogging() ?? 'not found'; + } else if ('conversation' in options) { + idForLogging = options.conversation?.idForLogging() ?? 'not found'; + } else { + const { conversationType } = options; + idForLogging = conversationType + ? getConversationIdForLogging(conversationType) + : 'not found'; + } + + const additionalText = additional ? `/${additional}` : ''; + + return `${source}(${idForLogging}${additionalText})`; +} + export class CallingClass { readonly #videoCapturer: GumVideoCapturer; @@ -478,12 +519,18 @@ export class CallingClass { } )) > { - log.info('CallingClass.startCallingLobby()'); + const logId = getLogId({ + source: 'CallingClass.startCallingLobby', + conversationType: conversation, + }); + log.info(logId); const callMode = getConversationCallMode(conversation); switch (callMode) { case null: - log.error('Conversation does not support calls, new call not allowed.'); + log.error( + `${logId}: Conversation does not support calls, new call not allowed.` + ); return; case CallMode.Direct: { const conversationModel = window.ConversationController.get( @@ -493,7 +540,9 @@ export class CallingClass { !conversationModel || !this.#getRemoteUserIdFromConversation(conversationModel) ) { - log.error('Missing remote user identifier, new call not allowed.'); + log.error( + `${logId}: Missing remote user identifier, new call not allowed.` + ); return; } break; @@ -502,7 +551,7 @@ export class CallingClass { break; case CallMode.Adhoc: log.error( - 'startCallingLobby() not implemented for adhoc calls. Did you mean: startCallLinkLobby()?' + `${logId}: not implemented for adhoc calls. Did you mean: startCallLinkLobby()?` ); return; default: @@ -510,22 +559,24 @@ export class CallingClass { } if (!this.#reduxInterface) { - log.error('Missing uxActions, new call not allowed.'); + log.error(`${logId}: Missing uxActions, new call not allowed.`); return; } if (!this.#localDeviceId) { - log.error('Missing local device identifier, new call not allowed.'); + log.error( + `${logId}: Missing local device identifier, new call not allowed.` + ); return; } const haveMediaPermissions = await this.#requestPermissions(hasLocalVideo); if (!haveMediaPermissions) { - log.info('Permissions were denied, new call not allowed.'); + log.info(`${logId}: Permissions were denied, new call not allowed.`); return; } - log.info('CallingClass.startCallingLobby(): Starting lobby'); + log.info(`${logId}: Starting lobby`); await ensureSystemPermissions({ hasLocalAudio, hasLocalVideo }); // It's important that this function comes before any calls to @@ -558,6 +609,8 @@ export class CallingClass { 'Expected local audio to be enabled for direct call lobbies' ); enableLocalCameraIfNecessary(); + + log.info(`${logId}: Returning direct call`); return { callMode: CallMode.Direct, hasLocalAudio, @@ -570,7 +623,7 @@ export class CallingClass { !conversation.secretParams ) { log.error( - 'Conversation is missing required parameters. Cannot connect group call' + `${logId}: Conversation is missing required parameters. Cannot connect group call` ); return; } @@ -585,6 +638,7 @@ export class CallingClass { enableLocalCameraIfNecessary(); + log.info(`${logId}: Returning group call`); return { callMode: CallMode.Group, ...this.#formatGroupCallForRedux(groupCall), @@ -596,6 +650,12 @@ export class CallingClass { } stopCallingLobby(conversationId?: string): void { + const logId = getLogId({ + source: 'CallingClass.stopCallingLobby', + conversationId, + }); + log.info(logId); + this.disableLocalVideo(); this.#stopDeviceReselectionTimer(); this.#lastMediaDeviceSettings = undefined; @@ -696,6 +756,7 @@ export class CallingClass { const sfuUrl = this._sfuUrl; const logId = `deleteCallLink(${callLink.roomId})`; + log.info(logId); const callLinkRootKey = CallLinkRootKey.parse(callLink.rootKey); strictAssert(callLink.adminKey, 'Missing admin key'); @@ -813,6 +874,8 @@ export class CallingClass { const roomId = getRoomIdFromRootKey(callLinkRootKey); const logId = `readCallLink(${roomId})`; + log.info(logId); + const authCredentialPresentation = await getCallLinkAuthCredentialPresentation(callLinkRootKey); @@ -897,8 +960,7 @@ export class CallingClass { return; } - const idForLogging = getConversationIdForLogging(conversation.attributes); - const logId = `startOutgoingDirectCall(${idForLogging}`; + const logId = getLogId({ source: 'startOutgoingDirectCall', conversation }); log.info(logId); if (!this.#reduxInterface) { @@ -1144,6 +1206,9 @@ export class CallingClass { throw new Error('Missing SFU URL; not connecting group call'); } + const logId = getLogId({ source: 'connectGroupCall', conversationId }); + log.info(logId); + const groupIdBuffer = Buffer.from(Bytes.fromBase64(groupId)); let isRequestingMembershipProof = false; @@ -1171,7 +1236,7 @@ export class CallingClass { ); } } catch (err) { - log.error('Failed to fetch membership proof', err); + log.error(`${logId}: Failed to fetch membership proof`, err); } finally { isRequestingMembershipProof = false; } @@ -1182,7 +1247,9 @@ export class CallingClass { if (!outerGroupCall) { // This should be very rare, likely due to RingRTC not being able to get a lock // or memory or something like that. - throw new Error('Failed to get a group call instance; cannot start call'); + throw new Error( + `${logId} Failed to get a group call instance; cannot start call` + ); } outerGroupCall.connect(); @@ -1215,8 +1282,13 @@ export class CallingClass { return existing; } + const logId = `connectCallLinkCall(${roomId}`; + log.info(logId); + if (!this._sfuUrl) { - throw new Error('Missing SFU URL; not connecting group call link call'); + throw new Error( + `${logId}: Missing SFU URL; not connecting group call link call` + ); } const outerGroupCall = RingRTC.getCallLinkCall( @@ -1232,7 +1304,9 @@ export class CallingClass { if (!outerGroupCall) { // This should be very rare, likely due to RingRTC not being able to get a lock // or memory or something like that. - throw new Error('Failed to get a group call instance; cannot start call'); + throw new Error( + `${logId}: Failed to get a group call instance; cannot start call` + ); } outerGroupCall.connect(); @@ -1249,21 +1323,20 @@ export class CallingClass { hasLocalVideo: boolean, shouldRing: boolean ): Promise { - const conversation = - window.ConversationController.get(conversationId)?.format(); + const conversation = window.ConversationController.get(conversationId); if (!conversation) { - log.error('Missing conversation; not joining group call'); + log.error('joinGroupCall: Missing conversation; not joining group call'); return; } - const logId = `joinGroupCall(${getConversationIdForLogging(conversation)})`; + const logId = getLogId({ + source: 'joinGroupCall', + conversation, + }); log.info(logId); - if ( - !conversation.groupId || - !conversation.publicParams || - !conversation.secretParams - ) { + const { groupId, publicParams, secretParams } = conversation.attributes; + if (!groupId || !publicParams || !secretParams) { log.error( `${logId}: Conversation is missing required parameters. Cannot join group call` ); @@ -1281,9 +1354,9 @@ export class CallingClass { await this.#startDeviceReselectionTimer(); const groupCall = this.connectGroupCall(conversationId, { - groupId: conversation.groupId, - publicParams: conversation.publicParams, - secretParams: conversation.secretParams, + groupId, + publicParams, + secretParams, }); groupCall.setOutgoingAudioMuted(!hasLocalAudio); @@ -1567,6 +1640,8 @@ export class CallingClass { } const logId = `sendProfileKeysForAdhocCall aci=${aci}`; + log.info(logId); + const conversation = window.ConversationController.lookupOrCreate({ serviceId: aci, reason, @@ -1925,7 +2000,10 @@ export class CallingClass { return false; } - const logId = `sendGroupCallUpdateMessage/${conversation.idForLogging()}`; + const logId = getLogId({ + source: 'sendGroupCallUpdateMessage', + conversation, + }); const groupV2 = conversation.getGroupV2Info(); if (!groupV2) { @@ -1954,11 +2032,15 @@ export class CallingClass { conversationId: string, asVideoCall: boolean ): Promise { - log.info('CallingClass.acceptDirectCall()'); + const logId = getLogId({ + source: 'CallingClass.acceptDirectCall', + conversationId, + }); + log.info(logId); const callId = this.#getCallIdForConversation(conversationId); if (!callId) { - log.warn('Trying to accept a non-existent call'); + log.warn(`${logId}: Trying to accept a non-existent call`); return; } @@ -1973,17 +2055,23 @@ export class CallingClass { RingRTC.setVideoRenderer(callId, this.videoRenderer); RingRTC.accept(callId, asVideoCall); } else { - log.info('Permissions were denied, call not allowed, hanging up.'); + log.info( + `${logId}: Permissions were denied, call not allowed, hanging up.` + ); RingRTC.hangup(callId); } } declineDirectCall(conversationId: string): void { - log.info('CallingClass.declineDirectCall()'); + const logId = getLogId({ + source: 'CallingClass.declineDirectCall', + conversationId, + }); + log.info(logId); const callId = this.#getCallIdForConversation(conversationId); if (!callId) { - log.warn('declineDirectCall: Trying to decline a non-existent call'); + log.warn(`${logId}: Trying to decline a non-existent call`); return; } @@ -1991,7 +2079,11 @@ export class CallingClass { } declineGroupCall(conversationId: string, ringId: bigint): void { - log.info('CallingClass.declineGroupCall()'); + const logId = getLogId({ + source: 'CallingClass.declineGroupCall', + conversationId, + }); + log.info(logId); const groupId = window.ConversationController.get(conversationId)?.get('groupId'); @@ -2011,13 +2103,16 @@ export class CallingClass { } hangup(conversationId: string, reason: string): void { - log.info(`CallingClass.hangup(${conversationId}): ${reason}`); + const logId = getLogId({ + source: 'CallingClass.hangup', + conversationId, + additional: reason, + }); + log.info(logId); const specificCall = getOwn(this.#callsLookup, conversationId); if (!specificCall) { - log.error( - `hangup: Trying to hang up a non-existent call for conversation ${conversationId}` - ); + log.error(`${logId}: Trying to hang up a non-existent call`); } ipcRenderer.send( @@ -2026,10 +2121,10 @@ export class CallingClass { ); const entries = Object.entries(this.#callsLookup); - log.info(`hangup: ${entries.length} call(s) to hang up...`); + log.info(`${logId}: ${entries.length} call(s) to hang up...`); entries.forEach(([callConversationId, call]) => { - log.info(`hangup: Hanging up conversation ${callConversationId}`); + log.info(`${logId}: Hanging up conversation ${callConversationId}`); if (call instanceof Call) { RingRTC.hangup(call.callId); } else if (call instanceof GroupCall) { @@ -2042,7 +2137,7 @@ export class CallingClass { } }); - log.info('hangup: Done.'); + log.info(`${logId}: Done.`); } hangupAllCalls(reason: string): void { @@ -2502,6 +2597,7 @@ export class CallingClass { callingMessage: Proto.ICallMessage ): Promise { const logId = `CallingClass.handleCallingMessage(${envelope.timestamp})`; + log.info(logId); const enableIncomingCalls = window.Events.getIncomingCallNotification(); if (callingMessage.offer && !enableIncomingCalls) { @@ -2793,7 +2889,12 @@ export class CallingClass { }); } - const logId = `handleGroupCallRingUpdate(${conversation.idForLogging()})`; + const logId = getLogId({ + source: 'CallingClass.handleGroupCallRingUpdate', + conversation, + }); + log.info(logId); + if (conversation.isBlocked()) { log.warn(`${logId}: is blocked`); return; @@ -2928,23 +3029,29 @@ export class CallingClass { // If we return null here, we hang up the call. async #handleIncomingCall(call: Call): Promise { - log.info('CallingClass.handleIncomingCall()'); - if (!this.#reduxInterface || !this.#localDeviceId) { - log.error('Missing required objects, ignoring incoming call.'); + log.error( + 'handleIncomingCall: Missing required objects, ignoring incoming call.' + ); return false; } const conversation = window.ConversationController.get(call.remoteUserId); if (!conversation) { - log.error('Missing conversation, ignoring incoming call.'); + log.error( + 'handleIncomingCall: Missing conversation, ignoring incoming call.' + ); return false; } + const logId = getLogId({ + source: 'CallingClass.handleIncomingCall', + conversation, + }); + log.info(logId); + if (conversation.isBlocked()) { - log.warn( - `handleIncomingCall(): ${conversation.idForLogging()} is blocked` - ); + log.warn(`${logId}: ${conversation.idForLogging()} is blocked`); return false; } try { @@ -2956,9 +3063,7 @@ export class CallingClass { verifiedEnum === window.textsecure.storage.protocol.VerifiedStatus.UNVERIFIED ) { - log.info( - `Peer is not trusted, ignoring incoming call for conversation: ${conversation.idForLogging()}` - ); + log.info(`${logId}: Peer is not trusted, ignoring incoming call`); const localCallEvent = LocalCallEvent.Missed; const peerId = getPeerIdFromConversation(conversation.attributes); @@ -2973,6 +3078,14 @@ export class CallingClass { return false; } + if (call.endedReason) { + log.warn( + `${logId}: Returning early, call ended with reason ${call.endedReason}` + ); + this.#reduxInterface?.declineCall({ conversationId: conversation.id }); + return false; + } + this.#attachToCall(conversation, call); this.#reduxInterface.receiveIncomingDirectCall({ @@ -2980,9 +3093,10 @@ export class CallingClass { isVideoCall: call.isVideoCall, }); + log.warn(`${logId}: Returning true`); return true; } catch (err) { - log.error(`Ignoring incoming call: ${Errors.toLogFormat(err)}`); + log.error(`${logId}: Ignoring incoming call: ${Errors.toLogFormat(err)}`); return false; } } @@ -2998,9 +3112,16 @@ export class CallingClass { ) { const conversation = window.ConversationController.get(remoteUserId); if (!conversation) { + log.warn('handleAutoEndedIncomingCallRequest: Conversation not found'); return; } + const logId = getLogId({ + source: 'handleAutoEndedIncomingCallRequest', + conversation, + }); + log.info(logId); + const callId = Long.fromValue(callIdValue).toString(); const peerId = getPeerIdFromConversation(conversation.attributes); @@ -3028,9 +3149,7 @@ export class CallingClass { ); if (!this.#reduxInterface) { - log.error( - 'handleAutoEndedIncomingCallRequest: Unable to update redux for call' - ); + log.error(`${logId}: Unable to update redux for call`); } this.#reduxInterface?.callStateChange({ acceptedTime: null, @@ -3055,6 +3174,12 @@ export class CallingClass { return; } + const logId = getLogId({ + source: 'CallingClass.attachToCall', + conversation, + }); + log.info(logId); + let acceptedTime: number | null = null; // eslint-disable-next-line no-param-reassign @@ -3263,21 +3388,45 @@ export class CallingClass { } if (!window.textsecure.messaging) { - log.error('handleStartCall: offline!'); + log.error('CallingClass.handleStartCall: offline!'); + return false; + } + const conversation = window.ConversationController.get(call.remoteUserId); + if (!conversation) { + log.error( + 'CallingClass.handleStartCall: Missing conversation, ignoring incoming call.' + ); + return false; + } + + const logId = getLogId({ + source: 'CallingClass.handleStartCall', + conversation, + }); + log.info(logId); + + if (call.endedReason) { + log.warn( + `${logId}: Returning early, call ended with reason ${call.endedReason}` + ); + this.#reduxInterface?.declineCall({ conversationId: conversation.id }); return false; } const iceServerConfig = await window.textsecure.messaging.server.getIceServers(); - const shouldRelayCalls = window.Events.getAlwaysRelayCalls(); - - const conversation = window.ConversationController.get(call.remoteUserId); - if (!conversation) { - log.error('Missing conversation, ignoring incoming call.'); + // We do this again, since getIceServers is a call that can take some time + if (call.endedReason) { + log.warn( + `${logId}: Returning early, call ended with reason ${call.endedReason}` + ); + this.#reduxInterface?.declineCall({ conversationId: conversation.id }); return false; } + const shouldRelayCalls = window.Events.getAlwaysRelayCalls(); + // If the peer is not a Signal Connection, force IP hiding. const isContactUntrusted = !isSignalConnection(conversation.attributes); diff --git a/ts/state/ducks/calling.ts b/ts/state/ducks/calling.ts index 9ef6c9072..0e755ca35 100644 --- a/ts/state/ducks/calling.ts +++ b/ts/state/ducks/calling.ts @@ -1284,7 +1284,7 @@ function declineCall( const call = getOwn(getState().calling.callsByConversation, conversationId); if (!call) { - log.error('Trying to decline a non-existent call'); + log.warn('Trying to decline a non-existent call'); return; }