Feature/fga/log tags voip

matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt

@@ -0,0 +1,37 @@
+/*
+ * 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
+
+/**
+ * Parent class for custom logger tags. Can be used with Timber :
+ *
+ * val loggerTag = LoggerTag("MyTag", LoggerTag.VOIP)
+ * Timber.tag(loggerTag.value).v("My log message")
+ */
+open class LoggerTag(private val _value: String, private val parentTag: LoggerTag? = null) {
+
+    object VOIP : LoggerTag("VOIP", null)
+
+    val value: String
+        get() {
+            return if (parentTag == null) {
+                _value
+            } else {
+                "${parentTag.value}/$_value"
+            }
+        }
+}

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/call/CallEventProcessor.kt

@@ -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 loggerTag = 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(loggerTag.value).w("Event with no room id ${event.eventId}")
         }
         callSignalingHandler.onCallEvent(event)
     }

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/call/CallSignalingHandler.kt

@@ -16,6 +16,7 @@
 
 package org.matrix.android.sdk.internal.session.call
 
+import org.matrix.android.sdk.api.logger.LoggerTag
 import org.matrix.android.sdk.api.session.call.CallListener
 import org.matrix.android.sdk.api.session.call.CallState
 import org.matrix.android.sdk.api.session.call.MxCall
@@ -36,6 +37,8 @@ import org.matrix.android.sdk.internal.session.SessionScope
 import timber.log.Timber
 import javax.inject.Inject
 
+private val loggerTag = 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(loggerTag.value).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(loggerTag.value).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(loggerTag.value).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(loggerTag.value).v("Ignoring hangup from party ID ${content.partyId} we have chosen party ID ${call.opponentPartyId}")
             return
         }
         if (call.state !is CallState.Ended) {
@@ -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(loggerTag.value).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(loggerTag.value).d("Ignoring already known call invite")
             return
         }
         val incomingCall = mxCallFactory.createIncomingCall(
@@ -214,7 +223,8 @@ 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(loggerTag.value)
+                        .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 +241,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(loggerTag.value).v("Call with id $callId is null")
         }
         return currentCall
     }

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/call/DefaultCallSignalingService.kt

@@ -21,7 +21,6 @@ import org.matrix.android.sdk.api.session.call.CallSignalingService
 import org.matrix.android.sdk.api.session.call.MxCall
 import org.matrix.android.sdk.api.session.call.TurnServerResponse
 import org.matrix.android.sdk.internal.session.SessionScope
-import timber.log.Timber
 import javax.inject.Inject
 
 @SessionScope
@@ -51,7 +50,6 @@ internal class DefaultCallSignalingService @Inject constructor(
     }
 
     override fun getCallWithId(callId: String): MxCall? {
-        Timber.v("## VOIP getCallWithId $callId all calls ${activeCallHandler.getActiveCallsLiveData().value?.map { it.callId }}")
         return activeCallHandler.getCallWithId(callId)
     }
 

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/call/model/MxCallImpl.kt

@@ -17,6 +17,7 @@
 package org.matrix.android.sdk.internal.session.call.model
 
 import org.matrix.android.sdk.api.MatrixConfiguration
+import org.matrix.android.sdk.api.logger.LoggerTag
 import org.matrix.android.sdk.api.session.call.CallIdGenerator
 import org.matrix.android.sdk.api.session.call.CallState
 import org.matrix.android.sdk.api.session.call.MxCall
@@ -48,6 +49,8 @@ import org.matrix.android.sdk.internal.session.room.send.queue.EventSenderProces
 import timber.log.Timber
 import java.math.BigDecimal
 
+private val loggerTag = LoggerTag("MxCallImpl", LoggerTag.VOIP)
+
 internal class MxCallImpl(
         override val callId: String,
         override val isOutgoing: Boolean,
@@ -94,7 +97,7 @@ internal class MxCallImpl(
             try {
                 it.onStateUpdate(this)
             } catch (failure: Throwable) {
-                Timber.d("dispatchStateChange failed for call $callId : ${failure.localizedMessage}")
+                Timber.tag(loggerTag.value).d("dispatchStateChange failed for call $callId : ${failure.localizedMessage}")
             }
         }
     }
@@ -110,7 +113,7 @@ internal class MxCallImpl(
 
     override fun offerSdp(sdpString: String) {
         if (!isOutgoing) return
-        Timber.v("## VOIP offerSdp $callId")
+        Timber.tag(loggerTag.value).v("offerSdp $callId")
         state = CallState.Dialing
         CallInviteContent(
                 callId = callId,
@@ -125,7 +128,7 @@ internal class MxCallImpl(
     }
 
     override fun sendLocalCallCandidates(candidates: List<CallCandidate>) {
-        Timber.v("Send local call canditates $callId: $candidates")
+        Timber.tag(loggerTag.value).v("Send local call canditates $callId: $candidates")
         CallCandidatesContent(
                 callId = callId,
                 partyId = ourPartyId,
@@ -142,11 +145,11 @@ internal class MxCallImpl(
 
     override fun reject() {
         if (opponentVersion < 1) {
-            Timber.v("Opponent version is less than 1 ($opponentVersion): sending hangup instead of reject")
+            Timber.tag(loggerTag.value).v("Opponent version is less than 1 ($opponentVersion): sending hangup instead of reject")
             hangUp(EndCallReason.USER_HANGUP)
             return
         }
-        Timber.v("## VOIP reject $callId")
+        Timber.tag(loggerTag.value).v("reject $callId")
         CallRejectContent(
                 callId = callId,
                 partyId = ourPartyId,
@@ -158,7 +161,7 @@ internal class MxCallImpl(
     }
 
     override fun hangUp(reason: EndCallReason?) {
-        Timber.v("## VOIP hangup $callId")
+        Timber.tag(loggerTag.value).v("hangup $callId")
         CallHangupContent(
                 callId = callId,
                 partyId = ourPartyId,
@@ -171,7 +174,7 @@ internal class MxCallImpl(
     }
 
     override fun accept(sdpString: String) {
-        Timber.v("## VOIP accept $callId")
+        Timber.tag(loggerTag.value).v("accept $callId")
         if (isOutgoing) return
         state = CallState.Answering
         CallAnswerContent(
@@ -186,7 +189,7 @@ internal class MxCallImpl(
     }
 
     override fun negotiate(sdpString: String, type: SdpType) {
-        Timber.v("## VOIP negotiate $callId")
+        Timber.tag(loggerTag.value).v("negotiate $callId")
         CallNegotiateContent(
                 callId = callId,
                 partyId = ourPartyId,
@@ -199,7 +202,7 @@ internal class MxCallImpl(
     }
 
     override fun selectAnswer() {
-        Timber.v("## VOIP select answer $callId")
+        Timber.tag(loggerTag.value).v("select answer $callId")
         if (isOutgoing) return
         state = CallState.Answering
         CallSelectAnswerContent(
@@ -220,7 +223,7 @@ internal class MxCallImpl(
         val profileInfo = try {
             getProfileInfoTask.execute(profileInfoParams)
         } catch (failure: Throwable) {
-            Timber.v("Fail fetching profile info of $targetUserId while transferring call")
+            Timber.tag(loggerTag.value).v("Fail fetching profile info of $targetUserId while transferring call")
             null
         }
         CallReplacesContent(

vector/src/main/java/im/vector/app/core/services/CallService.kt

@@ -37,10 +37,13 @@ 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.session.room.model.call.EndCallReason
 import org.matrix.android.sdk.api.util.MatrixItem
 import timber.log.Timber
 
+private val loggerTag = LoggerTag("CallService", LoggerTag.VOIP)
+
 /**
  * Foreground service to manage calls
  */
@@ -93,7 +96,7 @@ class CallService : VectorService() {
     }
 
     override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
-        Timber.v("## VOIP onStartCommand $intent")
+        Timber.tag(loggerTag.value).v("onStartCommand $intent")
         if (mediaSession == null) {
             mediaSession = MediaSessionCompat(applicationContext, CallService::class.java.name).apply {
                 setCallback(mediaSessionButtonCallback)
@@ -150,15 +153,15 @@ class CallService : VectorService() {
      *
      */
     private fun displayIncomingCallNotification(intent: Intent) {
-        Timber.v("## VOIP displayIncomingCallNotification $intent")
+        Timber.tag(loggerTag.value).v("displayIncomingCallNotification $intent")
         val callId = intent.getStringExtra(EXTRA_CALL_ID) ?: ""
         val call = callManager.getCallById(callId) ?: return Unit.also {
             handleUnexpectedState(callId)
         }
         val callInformation = call.toCallInformation()
         val isVideoCall = call.mxCall.isVideoCall
         val fromBg = intent.getBooleanExtra(EXTRA_IS_IN_BG, false)
-        Timber.v("displayIncomingCallNotification : display the dedicated notification")
+        Timber.tag(loggerTag.value).v("displayIncomingCallNotification : display the dedicated notification")
         val incomingCallAlert = IncomingCallAlert(callId,
                 shouldBeDisplayedIn = { activity ->
                     if (activity is VectorCallActivity) {
@@ -197,7 +200,7 @@ class CallService : VectorService() {
         alertManager.cancelAlert(callId)
         val terminatedCall = knownCalls.firstOrNull { it.callId == callId }
         if (terminatedCall == null) {
-            Timber.v("Call terminated for unknown call $callId$")
+            Timber.tag(loggerTag.value).v("Call terminated for unknown call $callId$")
             handleUnexpectedState(callId)
             return
         }
@@ -207,13 +210,11 @@ class CallService : VectorService() {
             myStopSelf()
         }
         val wasConnected = connectedCallIds.remove(callId)
+        val notification = notificationUtils.buildCallEndedNotification(terminatedCall.isVideoCall)
+        notificationManager.notify(callId.hashCode(), notification)
         if (!wasConnected && !terminatedCall.isOutgoing && !rejected && endCallReason != EndCallReason.ANSWERED_ELSEWHERE) {
-            val notification = notificationUtils.buildCallMissedNotification(terminatedCall)
-            notificationManager.cancel(callId.hashCode())
-            notificationManager.notify(MISSED_CALL_TAG, terminatedCall.nativeRoomId.hashCode(), notification)
-        } else {
-            val notification = notificationUtils.buildCallEndedNotification(terminatedCall.isVideoCall)
-            notificationManager.notify(callId.hashCode(), notification)
+            val missedCallNotification = notificationUtils.buildCallMissedNotification(terminatedCall)
+            notificationManager.notify(MISSED_CALL_TAG, terminatedCall.nativeRoomId.hashCode(), missedCallNotification)
         }
     }
 
@@ -232,7 +233,7 @@ class CallService : VectorService() {
             handleUnexpectedState(callId)
         }
         val callInformation = call.toCallInformation()
-        Timber.v("displayOutgoingCallNotification : display the dedicated notification")
+        Timber.tag(loggerTag.value).v("displayOutgoingCallNotification : display the dedicated notification")
         val notification = notificationUtils.buildOutgoingRingingCallNotification(
                 call = call,
                 title = callInformation.opponentMatrixItem?.getBestName() ?: callInformation.opponentUserId
@@ -249,7 +250,7 @@ class CallService : VectorService() {
      * Display a call in progress notification.
      */
     private fun displayCallInProgressNotification(intent: Intent) {
-        Timber.v("## VOIP displayCallInProgressNotification")
+        Timber.tag(loggerTag.value).v("displayCallInProgressNotification")
         val callId = intent.getStringExtra(EXTRA_CALL_ID) ?: ""
         connectedCallIds.add(callId)
         val call = callManager.getCallById(callId) ?: return Unit.also {
@@ -270,7 +271,7 @@ class CallService : VectorService() {
     }
 
     private fun handleUnexpectedState(callId: String?) {
-        Timber.v("Fallback to clear everything")
+        Timber.tag(loggerTag.value).v("Fallback to clear everything")
         callRingPlayerIncoming?.stop()
         callRingPlayerOutgoing?.stop()
         if (callId != null) {