Start experiment on log tags

This commit is contained in:
ganfra 2021-07-22 10:12:46 +02:00
parent 98720ce4a5
commit 115f00ff1a
6 changed files with 135 additions and 88 deletions

View file

@ -0,0 +1,32 @@
/*
* Copyright (c) 2021 The Matrix.org Foundation C.I.C.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package org.matrix.android.sdk.api.logger
/**
* Some tags used on Timber.
*/
open class LoggerTag(private val value: String, private val parentTag: LoggerTag? = null) {
object VOIP : LoggerTag("VOIP", null)
val computedValue: String
get() {
if (parentTag == null) return value
return "${parentTag.computedValue}/$value"
}
}

View file

@ -20,11 +20,14 @@ import io.realm.Realm
import org.matrix.android.sdk.api.session.events.model.Event
import org.matrix.android.sdk.api.session.events.model.EventType
import org.matrix.android.sdk.internal.database.model.EventInsertType
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.internal.session.EventInsertLiveProcessor
import org.matrix.android.sdk.internal.session.SessionScope
import timber.log.Timber
import javax.inject.Inject
private val CallEventProcessorTag = LoggerTag("CallEventProcessor", LoggerTag.VOIP)
@SessionScope
internal class CallEventProcessor @Inject constructor(private val callSignalingHandler: CallSignalingHandler)
: EventInsertLiveProcessor {
@ -71,14 +74,8 @@ internal class CallEventProcessor @Inject constructor(private val callSignalingH
}
private fun dispatchToCallSignalingHandlerIfNeeded(event: Event) {
val now = System.currentTimeMillis()
event.roomId ?: return Unit.also {
Timber.w("Event with no room id ${event.eventId}")
}
val age = now - (event.ageLocalTs ?: now)
if (age > 40_000) {
// Too old to ring?
return
Timber.tag(CallEventProcessorTag.computedValue).w("Event with no room id ${event.eventId}")
}
callSignalingHandler.onCallEvent(event)
}

View file

@ -32,10 +32,13 @@ import org.matrix.android.sdk.api.session.room.model.call.CallRejectContent
import org.matrix.android.sdk.api.session.room.model.call.CallSelectAnswerContent
import org.matrix.android.sdk.api.session.room.model.call.CallSignalingContent
import org.matrix.android.sdk.internal.di.UserId
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.internal.session.SessionScope
import timber.log.Timber
import javax.inject.Inject
private val CallSignalingHandlerTag = LoggerTag("CallSignalingHandler", LoggerTag.VOIP)
@SessionScope
internal class CallSignalingHandler @Inject constructor(private val activeCallHandler: ActiveCallHandler,
private val mxCallFactory: MxCallFactory,
@ -111,12 +114,12 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
return
}
if (call.isOutgoing) {
Timber.v("Got selectAnswer for an outbound call: ignoring")
Timber.tag(CallSignalingHandlerTag.computedValue).v("Got selectAnswer for an outbound call: ignoring")
return
}
val selectedPartyId = content.selectedPartyId
if (selectedPartyId == null) {
Timber.w("Got nonsensical select_answer with null selected_party_id: ignoring")
Timber.tag(CallSignalingHandlerTag.computedValue).w("Got nonsensical select_answer with null selected_party_id: ignoring")
return
}
callListenersDispatcher.onCallSelectAnswerReceived(content)
@ -130,7 +133,7 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
return
}
if (call.opponentPartyId != null && !call.partyIdsMatches(content)) {
Timber.v("Ignoring candidates from party ID ${content.partyId} we have chosen party ID ${call.opponentPartyId}")
Timber.tag(CallSignalingHandlerTag.computedValue).v("Ignoring candidates from party ID ${content.partyId} we have chosen party ID ${call.opponentPartyId}")
return
}
callListenersDispatcher.onCallIceCandidateReceived(call, content)
@ -163,7 +166,7 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
// party ID must match (our chosen partner hanging up the call) or be undefined (we haven't chosen
// a partner yet but we're treating the hangup as a reject as per VoIP v0)
if (call.opponentPartyId != null && !call.partyIdsMatches(content)) {
Timber.v("Ignoring hangup from party ID ${content.partyId} we have chosen party ID ${call.opponentPartyId}")
Timber.tag(CallSignalingHandlerTag.computedValue).v("Ignoring hangup from party ID ${content.partyId} we have chosen party ID ${call.opponentPartyId}")
return
}
if (call.state != CallState.Terminated) {
@ -180,12 +183,18 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
if (event.roomId == null || event.senderId == null) {
return
}
val now = System.currentTimeMillis()
val age = now - (event.ageLocalTs ?: now)
if (age > 40_000 && event.getClearType() == EventType.CALL_INVITE) {
Timber.tag(CallSignalingHandlerTag.computedValue).w("Call invite is too old to ring.")
return
}
val content = event.getClearContent().toModel<CallInviteContent>() ?: return
content.callId ?: return
if (invitedCallIds.contains(content.callId)) {
// Call is already known, maybe due to fast lane. Ignore
Timber.d("Ignoring already known call invite")
Timber.tag(CallSignalingHandlerTag.computedValue).d("Ignoring already known call invite")
return
}
val incomingCall = mxCallFactory.createIncomingCall(
@ -214,7 +223,7 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
callListenersDispatcher.onCallManagedByOtherSession(content.callId)
} else {
if (call.opponentPartyId != null) {
Timber.v("Ignoring answer from party ID ${content.partyId} we already have an answer from ${call.opponentPartyId}")
Timber.tag(CallSignalingHandlerTag.computedValue).v("Ignoring answer from party ID ${content.partyId} we already have an answer from ${call.opponentPartyId}")
return
}
mxCallFactory.updateOutgoingCallWithOpponentData(call, event.senderId, content, content.capabilities)
@ -231,7 +240,7 @@ internal class CallSignalingHandler @Inject constructor(private val activeCallHa
activeCallHandler.getCallWithId(it)
}
if (currentCall == null) {
Timber.v("Call with id $callId is null")
Timber.tag(CallSignalingHandlerTag.computedValue).v("Call with id $callId is null")
}
return currentCall
}

View file

@ -37,9 +37,12 @@ import im.vector.app.features.home.AvatarRenderer
import im.vector.app.features.notifications.NotificationUtils
import im.vector.app.features.popup.IncomingCallAlert
import im.vector.app.features.popup.PopupAlertManager
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.api.util.MatrixItem
import timber.log.Timber
private val CallServiceTag = LoggerTag("CallService", LoggerTag.VOIP)
/**
* Foreground service to manage calls
*/
@ -91,7 +94,7 @@ class CallService : VectorService() {
}
override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
Timber.v("## VOIP onStartCommand $intent")
Timber.tag(CallServiceTag.computedValue).v("onStartCommand $intent")
if (mediaSession == null) {
mediaSession = MediaSessionCompat(applicationContext, CallService::class.java.name).apply {
setCallback(mediaSessionButtonCallback)
@ -115,19 +118,19 @@ class CallService : VectorService() {
callRingPlayerOutgoing?.start()
displayOutgoingRingingCallNotification(intent)
}
ACTION_ONGOING_CALL -> {
ACTION_ONGOING_CALL -> {
callRingPlayerIncoming?.stop()
callRingPlayerOutgoing?.stop()
displayCallInProgressNotification(intent)
}
ACTION_CALL_CONNECTING -> {
ACTION_CALL_CONNECTING -> {
// lower notification priority
displayCallInProgressNotification(intent)
// stop ringing
callRingPlayerIncoming?.stop()
callRingPlayerOutgoing?.stop()
}
ACTION_CALL_TERMINATED -> {
ACTION_CALL_TERMINATED -> {
handleCallTerminated(intent)
}
else -> {
@ -148,7 +151,7 @@ class CallService : VectorService() {
*
*/
private fun displayIncomingCallNotification(intent: Intent) {
Timber.v("## VOIP displayIncomingCallNotification $intent")
Timber.tag(CallServiceTag.computedValue).v("displayIncomingCallNotification $intent")
val callId = intent.getStringExtra(EXTRA_CALL_ID) ?: ""
val call = callManager.getCallById(callId) ?: return Unit.also {
handleUnexpectedState(callId)
@ -156,7 +159,7 @@ class CallService : VectorService() {
val isVideoCall = call.mxCall.isVideoCall
val fromBg = intent.getBooleanExtra(EXTRA_IS_IN_BG, false)
val opponentMatrixItem = getOpponentMatrixItem(call)
Timber.v("displayIncomingCallNotification : display the dedicated notification")
Timber.tag(CallServiceTag.computedValue).v("displayIncomingCallNotification : display the dedicated notification")
val incomingCallAlert = IncomingCallAlert(callId,
shouldBeDisplayedIn = { activity ->
if (activity is VectorCallActivity) {
@ -192,7 +195,7 @@ class CallService : VectorService() {
val callId = intent.getStringExtra(EXTRA_CALL_ID) ?: ""
alertManager.cancelAlert(callId)
if (!knownCalls.remove(callId)) {
Timber.v("Call terminated for unknown call $callId$")
Timber.tag(CallServiceTag.computedValue).v("Call terminated for unknown call $callId$")
handleUnexpectedState(callId)
return
}
@ -219,7 +222,7 @@ class CallService : VectorService() {
handleUnexpectedState(callId)
}
val opponentMatrixItem = getOpponentMatrixItem(call)
Timber.v("displayOutgoingCallNotification : display the dedicated notification")
Timber.tag(CallServiceTag.computedValue).v("displayOutgoingCallNotification : display the dedicated notification")
val notification = notificationUtils.buildOutgoingRingingCallNotification(
call = call,
title = opponentMatrixItem?.getBestName() ?: call.mxCall.opponentUserId
@ -236,7 +239,7 @@ class CallService : VectorService() {
* Display a call in progress notification.
*/
private fun displayCallInProgressNotification(intent: Intent) {
Timber.v("## VOIP displayCallInProgressNotification")
Timber.tag(CallServiceTag.computedValue).v("displayCallInProgressNotification")
val callId = intent.getStringExtra(EXTRA_CALL_ID) ?: ""
val call = callManager.getCallById(callId) ?: return Unit.also {
handleUnexpectedState(callId)
@ -256,7 +259,7 @@ class CallService : VectorService() {
}
private fun handleUnexpectedState(callId: String?) {
Timber.v("Fallback to clear everything")
Timber.tag(CallServiceTag.computedValue).v("Fallback to clear everything")
callRingPlayerIncoming?.stop()
callRingPlayerOutgoing?.stop()
if (callId != null) {

View file

@ -45,6 +45,7 @@ import kotlinx.coroutines.launch
import kotlinx.coroutines.withContext
import org.matrix.android.sdk.api.extensions.orFalse
import org.matrix.android.sdk.api.extensions.tryOrNull
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.api.session.Session
import org.matrix.android.sdk.api.session.call.CallIdGenerator
import org.matrix.android.sdk.api.session.call.CallState
@ -88,6 +89,8 @@ private const val AUDIO_TRACK_ID = "${STREAM_ID}a0"
private const val VIDEO_TRACK_ID = "${STREAM_ID}v0"
private val DEFAULT_AUDIO_CONSTRAINTS = MediaConstraints()
private val WebRtcCallTag = LoggerTag("WebRtcCall", LoggerTag.VOIP)
class WebRtcCall(
val mxCall: MxCall,
// This is where the call is placed from an ui perspective.
@ -192,7 +195,7 @@ class WebRtcCall(
.subscribe {
// omit empty :/
if (it.isNotEmpty()) {
Timber.v("## Sending local ice candidates to call")
Timber.tag(WebRtcCallTag.computedValue).v("Sending local ice candidates to call")
// it.forEach { peerConnection?.addIceCandidate(it) }
mxCall.sendLocalCallCandidates(it.mapToCallCandidate())
}
@ -210,7 +213,7 @@ class WebRtcCall(
fun onRenegotiationNeeded(restartIce: Boolean) {
sessionScope?.launch(dispatcher) {
if (mxCall.state != CallState.CreateOffer && mxCall.opponentVersion == 0) {
Timber.v("Opponent does not support renegotiation: ignoring onRenegotiationNeeded event")
Timber.tag(WebRtcCallTag.computedValue).v("Opponent does not support renegotiation: ignoring onRenegotiationNeeded event")
return@launch
}
val constraints = MediaConstraints()
@ -218,7 +221,7 @@ class WebRtcCall(
constraints.mandatory.add(MediaConstraints.KeyValuePair("IceRestart", "true"))
}
val peerConnection = peerConnection ?: return@launch
Timber.v("## VOIP creating offer...")
Timber.tag(WebRtcCallTag.computedValue).v("creating offer...")
makingOffer = true
try {
val sessionDescription = peerConnection.awaitCreateOffer(constraints) ?: return@launch
@ -238,7 +241,7 @@ class WebRtcCall(
}
} catch (failure: Throwable) {
// Need to handle error properly.
Timber.v("Failure while creating offer")
Timber.tag(WebRtcCallTag.computedValue).v("Failure while creating offer")
} finally {
makingOffer = false
}
@ -267,7 +270,7 @@ class WebRtcCall(
}
}
}
Timber.v("## VOIP creating peer connection...with iceServers $iceServers ")
Timber.tag(WebRtcCallTag.computedValue).v("creating peer connection...with iceServers $iceServers ")
val rtcConfig = PeerConnection.RTCConfiguration(iceServers).apply {
sdpSemantics = PeerConnection.SdpSemantics.UNIFIED_PLAN
}
@ -314,7 +317,7 @@ class WebRtcCall(
fun acceptIncomingCall() {
sessionScope?.launch {
Timber.v("## VOIP acceptIncomingCall from state ${mxCall.state}")
Timber.tag(WebRtcCallTag.computedValue).v("acceptIncomingCall from state ${mxCall.state}")
if (mxCall.state == CallState.LocalRinging) {
internalAcceptIncomingCall()
}
@ -333,7 +336,7 @@ class WebRtcCall(
sender.dtmf()?.insertDtmf(digit, 100, 70)
return@launch
} catch (failure: Throwable) {
Timber.v("Fail to send Dtmf digit")
Timber.tag(WebRtcCallTag.computedValue).v("Fail to send Dtmf digit")
}
}
}
@ -342,7 +345,7 @@ class WebRtcCall(
fun attachViewRenderers(localViewRenderer: SurfaceViewRenderer?, remoteViewRenderer: SurfaceViewRenderer, mode: String?) {
sessionScope?.launch(dispatcher) {
Timber.v("## VOIP attachViewRenderers localRendeder $localViewRenderer / $remoteViewRenderer")
Timber.tag(WebRtcCallTag.computedValue).v("attachViewRenderers localRendeder $localViewRenderer / $remoteViewRenderer")
localSurfaceRenderers.addIfNeeded(localViewRenderer)
remoteSurfaceRenderers.addIfNeeded(remoteViewRenderer)
when (mode) {
@ -389,7 +392,7 @@ class WebRtcCall(
}
private suspend fun detachRenderersInternal(renderers: List<SurfaceViewRenderer>?) = withContext(dispatcher) {
Timber.v("## VOIP detachRenderers")
Timber.tag(WebRtcCallTag.computedValue).v("detachRenderers")
if (renderers.isNullOrEmpty()) {
// remove all sinks
localSurfaceRenderers.forEach {
@ -422,12 +425,12 @@ class WebRtcCall(
// 2. Access camera (if video call) + microphone, create local stream
createLocalStream()
attachViewRenderersInternal()
Timber.v("## VOIP remoteCandidateSource $remoteCandidateSource")
Timber.tag(WebRtcCallTag.computedValue).v("remoteCandidateSource $remoteCandidateSource")
remoteIceCandidateDisposable = remoteCandidateSource.subscribe({
Timber.v("## VOIP adding remote ice candidate $it")
Timber.tag(WebRtcCallTag.computedValue).v("adding remote ice candidate $it")
peerConnection?.addIceCandidate(it)
}, {
Timber.v("## VOIP failed to add remote ice candidate $it")
Timber.tag(WebRtcCallTag.computedValue).v("failed to add remote ice candidate $it")
})
// Now we wait for negotiation callback
}
@ -453,14 +456,14 @@ class WebRtcCall(
SessionDescription(SessionDescription.Type.OFFER, it)
}
if (offerSdp == null) {
Timber.v("We don't have any offer to process")
Timber.tag(WebRtcCallTag.computedValue).v("We don't have any offer to process")
return@withContext
}
Timber.v("Offer sdp for invite: ${offerSdp.description}")
Timber.tag(WebRtcCallTag.computedValue).v("Offer sdp for invite: ${offerSdp.description}")
try {
peerConnection?.awaitSetRemoteDescription(offerSdp)
} catch (failure: Throwable) {
Timber.v("Failure putting remote description")
Timber.tag(WebRtcCallTag.computedValue).v("Failure putting remote description")
endCall(true, CallHangupContent.Reason.UNKWOWN_ERROR)
return@withContext
}
@ -472,12 +475,12 @@ class WebRtcCall(
createAnswer()?.also {
mxCall.accept(it.description)
}
Timber.v("## VOIP remoteCandidateSource $remoteCandidateSource")
Timber.tag(WebRtcCallTag.computedValue).v("remoteCandidateSource $remoteCandidateSource")
remoteIceCandidateDisposable = remoteCandidateSource.subscribe({
Timber.v("## VOIP adding remote ice candidate $it")
Timber.tag(WebRtcCallTag.computedValue).v("adding remote ice candidate $it")
peerConnection?.addIceCandidate(it)
}, {
Timber.v("## VOIP failed to add remote ice candidate $it")
Timber.tag(WebRtcCallTag.computedValue).v("failed to add remote ice candidate $it")
})
}
@ -489,7 +492,7 @@ class WebRtcCall(
private fun createLocalStream() {
val peerConnectionFactory = peerConnectionFactoryProvider.get() ?: return
Timber.v("Create local stream for call ${mxCall.callId}")
Timber.tag(WebRtcCallTag.computedValue).v("Create local stream for call ${mxCall.callId}")
configureAudioTrack(peerConnectionFactory)
// add video track if needed
if (mxCall.isVideoCall) {
@ -502,7 +505,7 @@ class WebRtcCall(
val audioSource = peerConnectionFactory.createAudioSource(DEFAULT_AUDIO_CONSTRAINTS)
val audioTrack = peerConnectionFactory.createAudioTrack(AUDIO_TRACK_ID, audioSource)
audioTrack.setEnabled(true)
Timber.v("Add audio track $AUDIO_TRACK_ID to call ${mxCall.callId}")
Timber.tag(WebRtcCallTag.computedValue).v("Add audio track $AUDIO_TRACK_ID to call ${mxCall.callId}")
peerConnection?.addTrack(audioTrack, listOf(STREAM_ID))
localAudioSource = audioSource
localAudioTrack = audioTrack
@ -544,7 +547,7 @@ class WebRtcCall(
override fun onCameraClosed() {
super.onCameraClosed()
Timber.v("onCameraClosed")
Timber.tag(WebRtcCallTag.computedValue).v("onCameraClosed")
// This could happen if you open the camera app in chat
// We then register in order to restart capture as soon as the camera is available again
videoCapturerIsInError = true
@ -552,16 +555,16 @@ class WebRtcCall(
cameraAvailabilityCallback = object : CameraManager.AvailabilityCallback() {
override fun onCameraUnavailable(cameraId: String) {
super.onCameraUnavailable(cameraId)
Timber.v("On camera unavailable: $cameraId")
Timber.tag(WebRtcCallTag.computedValue).v("On camera unavailable: $cameraId")
}
override fun onCameraAccessPrioritiesChanged() {
super.onCameraAccessPrioritiesChanged()
Timber.v("onCameraAccessPrioritiesChanged")
Timber.tag(WebRtcCallTag.computedValue).v("onCameraAccessPrioritiesChanged")
}
override fun onCameraAvailable(cameraId: String) {
Timber.v("On camera available: $cameraId")
Timber.tag(WebRtcCallTag.computedValue).v("On camera available: $cameraId")
if (cameraId == camera.name) {
videoCapturer?.startCapture(currentCaptureFormat.width, currentCaptureFormat.height, currentCaptureFormat.fps)
cameraManager?.unregisterAvailabilityCallback(this)
@ -574,7 +577,7 @@ class WebRtcCall(
val videoSource = peerConnectionFactory.createVideoSource(videoCapturer.isScreencast)
val surfaceTextureHelper = SurfaceTextureHelper.create("CaptureThread", rootEglBase!!.eglBaseContext)
Timber.v("## VOIP Local video source created")
Timber.tag(WebRtcCallTag.computedValue).v("Local video source created")
videoCapturer.initialize(surfaceTextureHelper, context, videoSource.capturerObserver)
// HD
@ -582,7 +585,7 @@ class WebRtcCall(
this.videoCapturer = videoCapturer
val videoTrack = peerConnectionFactory.createVideoTrack(VIDEO_TRACK_ID, videoSource)
Timber.v("Add video track $VIDEO_TRACK_ID to call ${mxCall.callId}")
Timber.tag(WebRtcCallTag.computedValue).v("Add video track $VIDEO_TRACK_ID to call ${mxCall.callId}")
videoTrack.setEnabled(true)
peerConnection?.addTrack(videoTrack, listOf(STREAM_ID))
localVideoSource = videoSource
@ -592,7 +595,7 @@ class WebRtcCall(
fun setCaptureFormat(format: CaptureFormat) {
sessionScope?.launch(dispatcher) {
Timber.v("## VOIP setCaptureFormat $format")
Timber.tag(WebRtcCallTag.computedValue).v("setCaptureFormat $format")
videoCapturer?.changeCaptureFormat(format.width, format.height, format.fps)
currentCaptureFormat = format
}
@ -686,14 +689,14 @@ class WebRtcCall(
fun switchCamera() {
sessionScope?.launch(dispatcher) {
Timber.v("## VOIP switchCamera")
Timber.tag(WebRtcCallTag.computedValue).v("switchCamera")
if (mxCall.state is CallState.Connected && mxCall.isVideoCall) {
val oppositeCamera = getOppositeCameraIfAny() ?: return@launch
videoCapturer?.switchCamera(
object : CameraVideoCapturer.CameraSwitchHandler {
// Invoked on success. |isFrontCamera| is true if the new camera is front facing.
override fun onCameraSwitchDone(isFrontCamera: Boolean) {
Timber.v("## VOIP onCameraSwitchDone isFront $isFrontCamera")
Timber.tag(WebRtcCallTag.computedValue).v("onCameraSwitchDone isFront $isFrontCamera")
cameraInUse = oppositeCamera
localSurfaceRenderers.forEach {
it.get()?.setMirror(isFrontCamera)
@ -704,7 +707,7 @@ class WebRtcCall(
}
override fun onCameraSwitchError(errorDescription: String?) {
Timber.v("## VOIP onCameraSwitchError isFront $errorDescription")
Timber.tag(WebRtcCallTag.computedValue).v("onCameraSwitchError isFront $errorDescription")
}
}, oppositeCamera.name
)
@ -713,7 +716,7 @@ class WebRtcCall(
}
private suspend fun createAnswer(): SessionDescription? {
Timber.w("## VOIP createAnswer")
Timber.tag(WebRtcCallTag.computedValue).w("createAnswer")
val peerConnection = peerConnection ?: return null
val constraints = MediaConstraints().apply {
mandatory.add(MediaConstraints.KeyValuePair("OfferToReceiveAudio", "true"))
@ -724,7 +727,7 @@ class WebRtcCall(
peerConnection.awaitSetLocalDescription(localDescription)
localDescription
} catch (failure: Throwable) {
Timber.v("Fail to create answer")
Timber.tag(WebRtcCallTag.computedValue).v("Fail to create answer")
null
}
}
@ -765,7 +768,7 @@ class WebRtcCall(
sessionScope?.launch(dispatcher) {
// reportError("Weird-looking stream: " + stream);
if (stream.audioTracks.size > 1 || stream.videoTracks.size > 1) {
Timber.e("## VOIP StreamObserver weird looking stream: $stream")
Timber.tag(WebRtcCallTag.computedValue).e("## VOIP StreamObserver weird looking stream: $stream")
// TODO maybe do something more??
endCall(true)
return@launch
@ -829,7 +832,7 @@ class WebRtcCall(
if (it.sdpMid.isNullOrEmpty() || it.candidate.isNullOrEmpty()) {
return@forEach
}
Timber.v("## VOIP onCallIceCandidateReceived for call ${mxCall.callId} sdp: ${it.candidate}")
Timber.tag(WebRtcCallTag.computedValue).v("onCallIceCandidateReceived for call ${mxCall.callId} sdp: ${it.candidate}")
val iceCandidate = IceCandidate(it.sdpMid, it.sdpMLineIndex, it.candidate)
remoteCandidateSource.onNext(iceCandidate)
}
@ -838,7 +841,7 @@ class WebRtcCall(
fun onCallAnswerReceived(callAnswerContent: CallAnswerContent) {
sessionScope?.launch(dispatcher) {
Timber.v("## VOIP onCallAnswerReceived ${callAnswerContent.callId}")
Timber.tag(WebRtcCallTag.computedValue).v("onCallAnswerReceived ${callAnswerContent.callId}")
val sdp = SessionDescription(SessionDescription.Type.ANSWER, callAnswerContent.answer.sdp)
try {
peerConnection?.awaitSetRemoteDescription(sdp)
@ -858,7 +861,7 @@ class WebRtcCall(
val type = description?.type
val sdpText = description?.sdp
if (type == null || sdpText == null) {
Timber.i("Ignoring invalid m.call.negotiate event")
Timber.tag(WebRtcCallTag.computedValue).i("Ignoring invalid m.call.negotiate event")
return@launch
}
val peerConnection = peerConnection ?: return@launch
@ -873,7 +876,7 @@ class WebRtcCall(
ignoreOffer = !polite && offerCollision
if (ignoreOffer) {
Timber.i("Ignoring colliding negotiate event because we're impolite")
Timber.tag(WebRtcCallTag.computedValue).i("Ignoring colliding negotiate event because we're impolite")
return@launch
}
val prevOnHold = computeIsLocalOnHold()
@ -886,7 +889,7 @@ class WebRtcCall(
}
}
} catch (failure: Throwable) {
Timber.e(failure, "Failed to complete negotiation")
Timber.tag(WebRtcCallTag.computedValue).e(failure, "Failed to complete negotiation")
}
val nowOnHold = computeIsLocalOnHold()
wasLocalOnHold = nowOnHold
@ -909,7 +912,7 @@ class WebRtcCall(
val session = sessionProvider.get() ?: return@launch
val newAssertedIdentity = callAssertedIdentityContent.assertedIdentity ?: return@launch
if (newAssertedIdentity.id == null && newAssertedIdentity.displayName == null) {
Timber.v("Asserted identity received with no relevant information, skip")
Timber.tag(WebRtcCallTag.computedValue).v("Asserted identity received with no relevant information, skip")
return@launch
}
remoteAssertedIdentity = newAssertedIdentity

View file

@ -33,6 +33,7 @@ import im.vector.app.push.fcm.FcmHelper
import kotlinx.coroutines.asCoroutineDispatcher
import org.matrix.android.sdk.api.extensions.orFalse
import org.matrix.android.sdk.api.extensions.tryOrNull
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.api.session.Session
import org.matrix.android.sdk.api.session.call.CallListener
import org.matrix.android.sdk.api.session.call.CallState
@ -60,6 +61,8 @@ import javax.inject.Singleton
* Manage peerConnectionFactory & Peer connections outside of activity lifecycle to resist configuration changes
* Use app context
*/
private val WebRtcCallManagerTag = LoggerTag("WebRtcCallManager", LoggerTag.VOIP)
@Singleton
class WebRtcCallManager @Inject constructor(
private val context: Context,
@ -184,7 +187,7 @@ class WebRtcCallManager @Inject constructor(
fun getAdvertisedCalls() = advertisedCalls
fun headSetButtonTapped() {
Timber.v("## VOIP headSetButtonTapped")
Timber.tag(WebRtcCallManagerTag.computedValue).v("headSetButtonTapped")
val call = getCurrentCall() ?: return
if (call.mxCall.state is CallState.LocalRinging) {
call.acceptIncomingCall()
@ -197,12 +200,12 @@ class WebRtcCallManager @Inject constructor(
private fun createPeerConnectionFactoryIfNeeded() {
if (peerConnectionFactory != null) return
Timber.v("## VOIP createPeerConnectionFactory")
Timber.tag(WebRtcCallManagerTag.computedValue).v("createPeerConnectionFactory")
val eglBaseContext = rootEglBase?.eglBaseContext ?: return Unit.also {
Timber.e("## VOIP No EGL BASE")
Timber.tag(WebRtcCallManagerTag.computedValue).e("No EGL BASE")
}
Timber.v("## VOIP PeerConnectionFactory.initialize")
Timber.tag(WebRtcCallManagerTag.computedValue).v("PeerConnectionFactory.initialize")
PeerConnectionFactory.initialize(PeerConnectionFactory
.InitializationOptions.builder(context.applicationContext)
.createInitializationOptions()
@ -216,7 +219,7 @@ class WebRtcCallManager @Inject constructor(
/* enableH264HighProfile */
true)
val defaultVideoDecoderFactory = DefaultVideoDecoderFactory(eglBaseContext)
Timber.v("## VOIP PeerConnectionFactory.createPeerConnectionFactory ...")
Timber.tag(WebRtcCallManagerTag.computedValue).v("PeerConnectionFactory.createPeerConnectionFactory ...")
peerConnectionFactory = PeerConnectionFactory.builder()
.setOptions(options)
.setVideoEncoderFactory(defaultVideoEncoderFactory)
@ -225,7 +228,7 @@ class WebRtcCallManager @Inject constructor(
}
private fun onCallActive(call: WebRtcCall) {
Timber.v("## VOIP WebRtcPeerConnectionManager onCall active: ${call.mxCall.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).v("WebRtcPeerConnectionManager onCall active: ${call.mxCall.callId}")
val currentCall = getCurrentCall().takeIf { it != call }
currentCall?.updateRemoteOnHold(onHold = true)
audioManager.setMode(if (call.mxCall.isVideoCall) CallAudioManager.Mode.VIDEO_CALL else CallAudioManager.Mode.AUDIO_CALL)
@ -233,9 +236,9 @@ class WebRtcCallManager @Inject constructor(
}
private fun onCallEnded(callId: String) {
Timber.v("## VOIP WebRtcPeerConnectionManager onCall ended: $callId")
Timber.tag(WebRtcCallManagerTag.computedValue).v("WebRtcPeerConnectionManager onCall ended: $callId")
val webRtcCall = callsByCallId.remove(callId) ?: return Unit.also {
Timber.v("On call ended for unknown call $callId")
Timber.tag(WebRtcCallManagerTag.computedValue).v("On call ended for unknown call $callId")
}
CallService.onCallTerminated(context, callId)
callsByRoomId[webRtcCall.signalingRoomId]?.remove(webRtcCall)
@ -247,7 +250,7 @@ class WebRtcCallManager @Inject constructor(
}
// There is no active calls
if (getCurrentCall() == null) {
Timber.v("## VOIP Dispose peerConnectionFactory as there is no need to keep one")
Timber.tag(WebRtcCallManagerTag.computedValue).v("Dispose peerConnectionFactory as there is no need to keep one")
peerConnectionFactory?.dispose()
peerConnectionFactory = null
audioManager.setMode(CallAudioManager.Mode.DEFAULT)
@ -265,13 +268,13 @@ class WebRtcCallManager @Inject constructor(
suspend fun startOutgoingCall(nativeRoomId: String, otherUserId: String, isVideoCall: Boolean, transferee: WebRtcCall? = null) {
val signalingRoomId = callUserMapper?.getOrCreateVirtualRoomForRoom(nativeRoomId, otherUserId) ?: nativeRoomId
Timber.v("## VOIP startOutgoingCall in room $signalingRoomId to $otherUserId isVideo $isVideoCall")
Timber.tag(WebRtcCallManagerTag.computedValue).v("startOutgoingCall in room $signalingRoomId to $otherUserId isVideo $isVideoCall")
if (getCallsByRoomId(nativeRoomId).isNotEmpty()) {
Timber.w("## VOIP you already have a call in this room")
Timber.tag(WebRtcCallManagerTag.computedValue).w("you already have a call in this room")
return
}
if (getCurrentCall() != null && getCurrentCall()?.mxCall?.state !is CallState.Connected || getCalls().size >= 2) {
Timber.w("## VOIP cannot start outgoing call")
Timber.tag(WebRtcCallManagerTag.computedValue).w("cannot start outgoing call")
// Just ignore, maybe we could answer from other session?
return
}
@ -294,10 +297,10 @@ class WebRtcCallManager @Inject constructor(
}
override fun onCallIceCandidateReceived(mxCall: MxCall, iceCandidatesContent: CallCandidatesContent) {
Timber.v("## VOIP onCallIceCandidateReceived for call ${mxCall.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).v("onCallIceCandidateReceived for call ${mxCall.callId}")
val call = callsByCallId[iceCandidatesContent.callId]
?: return Unit.also {
Timber.w("onCallIceCandidateReceived for non active call? ${iceCandidatesContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallIceCandidateReceived for non active call? ${iceCandidatesContent.callId}")
}
call.onCallIceCandidateReceived(iceCandidatesContent)
}
@ -334,14 +337,14 @@ class WebRtcCallManager @Inject constructor(
}
override fun onCallInviteReceived(mxCall: MxCall, callInviteContent: CallInviteContent) {
Timber.v("## VOIP onCallInviteReceived callId ${mxCall.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).v("onCallInviteReceived callId ${mxCall.callId}")
val nativeRoomId = callUserMapper?.nativeRoomForVirtualRoom(mxCall.roomId) ?: mxCall.roomId
if (getCallsByRoomId(nativeRoomId).isNotEmpty()) {
Timber.w("## VOIP you already have a call in this room")
Timber.tag(WebRtcCallManagerTag.computedValue).w("you already have a call in this room")
return
}
if ((getCurrentCall() != null && getCurrentCall()?.mxCall?.state !is CallState.Connected) || getCalls().size >= 2) {
Timber.w("## VOIP receiving incoming call but cannot handle it")
Timber.tag(WebRtcCallManagerTag.computedValue).w("receiving incoming call but cannot handle it")
// Just ignore, maybe we could answer from other session?
return
}
@ -370,7 +373,7 @@ class WebRtcCallManager @Inject constructor(
override fun onCallAnswerReceived(callAnswerContent: CallAnswerContent) {
val call = callsByCallId[callAnswerContent.callId]
?: return Unit.also {
Timber.w("onCallAnswerReceived for non active call? ${callAnswerContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallAnswerReceived for non active call? ${callAnswerContent.callId}")
}
val mxCall = call.mxCall
// Update service state
@ -384,7 +387,7 @@ class WebRtcCallManager @Inject constructor(
override fun onCallHangupReceived(callHangupContent: CallHangupContent) {
val call = callsByCallId[callHangupContent.callId]
?: return Unit.also {
Timber.w("onCallHangupReceived for non active call? ${callHangupContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallHangupReceived for non active call? ${callHangupContent.callId}")
}
call.endCall(false)
}
@ -392,7 +395,7 @@ class WebRtcCallManager @Inject constructor(
override fun onCallRejectReceived(callRejectContent: CallRejectContent) {
val call = callsByCallId[callRejectContent.callId]
?: return Unit.also {
Timber.w("onCallRejectReceived for non active call? ${callRejectContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallRejectReceived for non active call? ${callRejectContent.callId}")
}
call.endCall(false)
}
@ -400,7 +403,7 @@ class WebRtcCallManager @Inject constructor(
override fun onCallSelectAnswerReceived(callSelectAnswerContent: CallSelectAnswerContent) {
val call = callsByCallId[callSelectAnswerContent.callId]
?: return Unit.also {
Timber.w("onCallSelectAnswerReceived for non active call? ${callSelectAnswerContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallSelectAnswerReceived for non active call? ${callSelectAnswerContent.callId}")
}
val selectedPartyId = callSelectAnswerContent.selectedPartyId
if (selectedPartyId != call.mxCall.ourPartyId) {
@ -413,13 +416,13 @@ class WebRtcCallManager @Inject constructor(
override fun onCallNegotiateReceived(callNegotiateContent: CallNegotiateContent) {
val call = callsByCallId[callNegotiateContent.callId]
?: return Unit.also {
Timber.w("onCallNegotiateReceived for non active call? ${callNegotiateContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallNegotiateReceived for non active call? ${callNegotiateContent.callId}")
}
call.onCallNegotiateReceived(callNegotiateContent)
}
override fun onCallManagedByOtherSession(callId: String) {
Timber.v("## VOIP onCallManagedByOtherSession: $callId")
Timber.tag(WebRtcCallManagerTag.computedValue).v("onCallManagedByOtherSession: $callId")
onCallEnded(callId)
}
@ -429,8 +432,8 @@ class WebRtcCallManager @Inject constructor(
}
val call = callsByCallId[callAssertedIdentityContent.callId]
?: return Unit.also {
Timber.w("onCallAssertedIdentityReceived for non active call? ${callAssertedIdentityContent.callId}")
Timber.tag(WebRtcCallManagerTag.computedValue).w("onCallAssertedIdentityReceived for non active call? ${callAssertedIdentityContent.callId}")
}
call.onCallAssertedIdentityReceived(callAssertedIdentityContent)
call.onCallAssertedIdentityReceived(callAssertedIdentityContent)
}
}