From fcc5181a2862a5dfff1c5f74731bad9d5ee2bd4f Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 11:26:36 +0100 Subject: [PATCH] Refactor Decryption Failure Tracker and report new properties --- .../java/im/vector/app/VectorApplication.kt | 3 + .../vector/app/core/di/ActiveSessionHolder.kt | 6 - .../features/analytics/DecryptionFailure.kt | 78 +++ .../analytics/DecryptionFailureTracker.kt | 319 ++++++--- .../home/room/detail/TimelineViewModel.kt | 1 - .../timeline/factory/TimelineItemFactory.kt | 4 +- .../analytics/DecryptionFailureTrackerTest.kt | 617 ++++++++++++++++++ .../im/vector/app/test/fakes/FakeSession.kt | 5 +- .../java/im/vector/app/test/fakes/FakeUri.kt | 1 + 9 files changed, 930 insertions(+), 104 deletions(-) create mode 100644 vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt create mode 100644 vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt diff --git a/vector-app/src/main/java/im/vector/app/VectorApplication.kt b/vector-app/src/main/java/im/vector/app/VectorApplication.kt index 7b41c12773..fe4cc3311b 100644 --- a/vector-app/src/main/java/im/vector/app/VectorApplication.kt +++ b/vector-app/src/main/java/im/vector/app/VectorApplication.kt @@ -51,6 +51,7 @@ import im.vector.app.core.debug.LeakDetector import im.vector.app.core.di.ActiveSessionHolder import im.vector.app.core.pushers.FcmHelper import im.vector.app.core.resources.BuildMeta +import im.vector.app.features.analytics.DecryptionFailureTracker import im.vector.app.features.analytics.VectorAnalytics import im.vector.app.features.call.webrtc.WebRtcCallManager import im.vector.app.features.configuration.VectorConfiguration @@ -100,6 +101,7 @@ class VectorApplication : @Inject lateinit var callManager: WebRtcCallManager @Inject lateinit var invitesAcceptor: InvitesAcceptor @Inject lateinit var autoRageShaker: AutoRageShaker + @Inject lateinit var decryptionFailureTracker: DecryptionFailureTracker @Inject lateinit var vectorFileLogger: VectorFileLogger @Inject lateinit var vectorAnalytics: VectorAnalytics @Inject lateinit var flipperProxy: FlipperProxy @@ -130,6 +132,7 @@ class VectorApplication : vectorAnalytics.init() invitesAcceptor.initialize() autoRageShaker.initialize() + decryptionFailureTracker.start() vectorUncaughtExceptionHandler.activate() // Remove Log handler statically added by Jitsi diff --git a/vector/src/main/java/im/vector/app/core/di/ActiveSessionHolder.kt b/vector/src/main/java/im/vector/app/core/di/ActiveSessionHolder.kt index 472d0896f9..5523c84994 100644 --- a/vector/src/main/java/im/vector/app/core/di/ActiveSessionHolder.kt +++ b/vector/src/main/java/im/vector/app/core/di/ActiveSessionHolder.kt @@ -23,7 +23,6 @@ import im.vector.app.core.pushers.UnregisterUnifiedPushUseCase import im.vector.app.core.services.GuardServiceStarter import im.vector.app.core.session.ConfigureAndStartSessionUseCase import im.vector.app.features.analytics.DecryptionFailureTracker -import im.vector.app.features.analytics.plan.Error import im.vector.app.features.call.webrtc.WebRtcCallManager import im.vector.app.features.crypto.keysrequest.KeyRequestHandler import im.vector.app.features.crypto.verification.IncomingVerificationRequestHandler @@ -75,11 +74,6 @@ class ActiveSessionHolder @Inject constructor( session.callSignalingService().addCallListener(callManager) imageManager.onSessionStarted(session) guardServiceStarter.start() - decryptionFailureTracker.currentModule = if (session.cryptoService().name() == "rust-sdk") { - Error.CryptoModule.Rust - } else { - Error.CryptoModule.Native - } } suspend fun clearActiveSession() { diff --git a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt new file mode 100644 index 0000000000..034b4cbcc3 --- /dev/null +++ b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt @@ -0,0 +1,78 @@ +/* + * Copyright (c) 2024 New Vector Ltd + * + * 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 im.vector.app.features.analytics + +import im.vector.app.features.analytics.plan.Error +import org.matrix.android.sdk.api.session.crypto.MXCryptoError + +data class DecryptionFailure( + val timeStamp: Long, + val roomId: String, + val failedEventId: String, + val error: MXCryptoError, + val wasVisibleOnScreen: Boolean, + val ownIdentityTrustedAtTimeOfDecryptionFailure: Boolean, + // If this is set, it means that the event was decrypted but late + val timeToDecryptMillis: Long? = null, + val isMatrixDotOrg: Boolean, + val isFederated: Boolean? = null, + val eventLocalAgeAtDecryptionFailure: Long? = null +) + +fun DecryptionFailure.toAnalyticsEvent(): Error { + val errorMsg = (error as? MXCryptoError.Base)?.technicalMessage ?: error.message + return Error( + context = "mxc_crypto_error_type|${errorMsg}", + domain = Error.Domain.E2EE, + name = this.error.toAnalyticsErrorName(), + // this is deprecated keep for backward compatibility + cryptoModule = Error.CryptoModule.Rust + ) +} + +fun DecryptionFailure.toCustomProperties(): Map { + val properties = mutableMapOf() + if (timeToDecryptMillis != null) { + properties["timeToDecryptMillis"] = timeToDecryptMillis + } else { + properties["timeToDecryptMillis"] = -1 + } + isFederated?.let { + properties["isFederated"] = it + } + properties["isMatrixDotOrg"] = isMatrixDotOrg + properties["wasVisibleToUser"] = wasVisibleOnScreen + properties["userTrustsOwnIdentity"] = ownIdentityTrustedAtTimeOfDecryptionFailure + eventLocalAgeAtDecryptionFailure?.let { + properties["eventLocalAgeAtDecryptionFailure"] = it + } + return properties +} + +private fun MXCryptoError.toAnalyticsErrorName(): Error.Name { + return if (this is MXCryptoError.Base) { + when (errorType) { + MXCryptoError.ErrorType.UNKNOWN_INBOUND_SESSION_ID, + MXCryptoError.ErrorType.KEYS_WITHHELD -> Error.Name.OlmKeysNotSentError + MXCryptoError.ErrorType.OLM -> Error.Name.OlmUnspecifiedError + MXCryptoError.ErrorType.UNKNOWN_MESSAGE_INDEX -> Error.Name.OlmIndexError + else -> Error.Name.UnknownError + } + } else { + Error.Name.UnknownError + } +} diff --git a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailureTracker.kt b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailureTracker.kt index d596741d53..53c5d87770 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailureTracker.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailureTracker.kt @@ -16,149 +16,280 @@ package im.vector.app.features.analytics -import im.vector.app.features.analytics.plan.Error -import im.vector.lib.core.utils.compat.removeIfCompat -import im.vector.lib.core.utils.flow.tickerFlow +import im.vector.app.ActiveSessionDataSource import im.vector.lib.core.utils.timer.Clock +import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.Job import kotlinx.coroutines.SupervisorJob -import kotlinx.coroutines.cancel +import kotlinx.coroutines.delay +import kotlinx.coroutines.flow.distinctUntilChanged import kotlinx.coroutines.flow.launchIn import kotlinx.coroutines.flow.onEach import kotlinx.coroutines.launch +import kotlinx.coroutines.sync.Mutex +import kotlinx.coroutines.sync.withLock +import org.matrix.android.sdk.api.MatrixPatterns +import org.matrix.android.sdk.api.session.LiveEventListener +import org.matrix.android.sdk.api.session.Session import org.matrix.android.sdk.api.session.crypto.MXCryptoError +import org.matrix.android.sdk.api.session.events.model.Event import org.matrix.android.sdk.api.session.room.timeline.TimelineEvent +import org.matrix.android.sdk.api.util.JsonDict +import timber.log.Timber import javax.inject.Inject import javax.inject.Singleton -private data class DecryptionFailure( - val timeStamp: Long, - val roomId: String, - val failedEventId: String, - val error: MXCryptoError.ErrorType -) -private typealias DetailedErrorName = Pair - +// If we can decrypt in less than 4s, we don't report private const val GRACE_PERIOD_MILLIS = 4_000 -private const val CHECK_INTERVAL = 2_000L + +// A tick to check when a decryption failure as exceeded the max time +private const val CHECK_INTERVAL = 10_000L + +// If we can't decrypt after 60s, we report failures +private const val MAX_WAIT_MILLIS = 60_000 /** - * Tracks decryption errors that are visible to the user. + * Tracks decryption errors. * When an error is reported it is not directly tracked via analytics, there is a grace period * that gives the app a few seconds to get the key to decrypt. + * + * Decrypted under 4s => No report + * Decrypted before MAX_WAIT_MILLIS => Report with time to decrypt + * Not Decrypted after MAX_WAIT_MILLIS => Report with time = -1 */ @Singleton class DecryptionFailureTracker @Inject constructor( private val analyticsTracker: AnalyticsTracker, + private val sessionDataSource: ActiveSessionDataSource, private val clock: Clock -) { +) : Session.Listener, LiveEventListener { - private val scope: CoroutineScope = CoroutineScope(SupervisorJob()) - private val failures = mutableListOf() + // The active session (set by the sessionDataSource) + private var activeSession: Session? = null + + // The coroutine scope to use for the tracker + private var scope: CoroutineScope = CoroutineScope(Dispatchers.IO + SupervisorJob()) + + // Map of eventId to tracked failure + // Only accessed on a `post` call, ensuring sequential access + private val trackedEventsMap = mutableMapOf() + + // List of eventId that have been reported, to avoid double reporting private val alreadyReported = mutableListOf() - var currentModule: Error.CryptoModule? = null + // Mutex to ensure sequential access to internal state + private val mutex = Mutex() - init { - start() - } + // Used to unsubscribe from the active session data source + private lateinit var activeSessionSourceDisposable: Job - fun start() { - tickerFlow(scope, CHECK_INTERVAL) - .onEach { - checkFailures() - }.launchIn(scope) + // The ticker job, to report permanent UTD (not decrypted after MAX_WAIT_MILLIS) + private var currentTicker: Job? = null + + /** + * Start the tracker + * + * @param scope The coroutine scope to use, exposed for tests. If null, it will use the default one + */ + fun start(scope: CoroutineScope? = null) { + if (scope != null) { + this.scope = scope + } + observeActiveSession() } fun stop() { - scope.cancel() + Timber.v("Stop DecryptionFailureTracker") + activeSessionSourceDisposable.cancel(CancellationException("Closing DecryptionFailureTracker")) + + activeSession?.removeListener(this) + activeSession?.eventStreamService()?.removeEventStreamListener(this) + activeSession = null } - fun e2eEventDisplayedInTimeline(event: TimelineEvent) { - scope.launch(Dispatchers.Default) { - val mCryptoError = event.root.mCryptoError - if (mCryptoError != null) { - addDecryptionFailure(DecryptionFailure(clock.epochMillis(), event.roomId, event.eventId, mCryptoError)) - } else { - removeFailureForEventId(event.eventId) + private fun post(block: suspend () -> Unit) { + scope.launch { + mutex.withLock { + block() } } } - /** - * Can be called when the timeline is disposed in order - * to grace those events as they are not anymore displayed on screen. - * */ - fun onTimeLineDisposed(roomId: String) { - scope.launch(Dispatchers.Default) { - synchronized(failures) { - failures.removeIfCompat { it.roomId == roomId } + private suspend fun rescheduleTicker() { + currentTicker = scope.launch { + Timber.v("Reschedule ticker") + delay(CHECK_INTERVAL) + post { + checkFailures() + currentTicker = null + if (trackedEventsMap.isNotEmpty()) { + // Reschedule + rescheduleTicker() + } + } + } + } + private fun observeActiveSession() { + activeSessionSourceDisposable = sessionDataSource.stream() + .distinctUntilChanged() + .onEach { + Timber.v("Active session changed ${it.getOrNull()?.myUserId}") + it.orNull()?.let { session -> + post { + onSessionActive(session) + } + } + }.launchIn(scope) + } + + private fun onSessionActive(session: Session) { + Timber.v("onSessionActive ${session.myUserId} previous: ${activeSession?.myUserId}") + val sessionId = session.sessionId + if (sessionId == activeSession?.sessionId) { + return + } + this.activeSession?.let { previousSession -> + previousSession.removeListener(this) + previousSession.eventStreamService().removeEventStreamListener(this) + // Do we want to clear the tracked events? + } + this.activeSession = session + session.addListener(this) + session.eventStreamService().addEventStreamListener(this) + } + + override fun onSessionStopped(session: Session) { + post { + this.activeSession = null + session.addListener(this) + session.eventStreamService().addEventStreamListener(this) + } + } + + // LiveEventListener callbacks + + override fun onEventDecrypted(event: Event, clearEvent: JsonDict) { + Timber.v("Event decrypted ${event.eventId}") + event.eventId?.let { + post { + handleEventDecrypted(it) } } } - private fun addDecryptionFailure(failure: DecryptionFailure) { - // de duplicate - synchronized(failures) { - if (failures.none { it.failedEventId == failure.failedEventId }) { - failures.add(failure) - } + override fun onEventDecryptionError(event: Event, cryptoError: MXCryptoError) { + Timber.v("Decryption error for event ${event.eventId} with error $cryptoError") + val session = activeSession ?: return + // track the event + post { + trackEvent(session, event, cryptoError) } } - private fun removeFailureForEventId(eventId: String) { - synchronized(failures) { - failures.removeIfCompat { it.failedEventId == eventId } + override fun onLiveToDeviceEvent(event: Event) {} + override fun onLiveEvent(roomId: String, event: Event) {} + override fun onPaginatedEvent(roomId: String, event: Event) {} + + private suspend fun trackEvent(session: Session, event: Event, error: MXCryptoError) { + Timber.v("Track event ${event.eventId}/${session.myUserId} time: ${clock.epochMillis()}") + val eventId = event.eventId + val roomId = event.roomId + if (eventId == null || roomId == null) return + if (trackedEventsMap.containsKey(eventId)) { + // already tracked + return } + val isOwnIdentityTrusted = session.cryptoService().crossSigningService().isCrossSigningVerified() + val userHS = MatrixPatterns.extractServerNameFromId(session.myUserId) + val messageSenderHs = event.senderId?.let { MatrixPatterns.extractServerNameFromId(it) } + Timber.v("senderHs: $messageSenderHs, userHS: $userHS, isOwnIdentityTrusted: $isOwnIdentityTrusted") + + val deviceCreationTs = session.cryptoService().getMyCryptoDevice().firstTimeSeenLocalTs + Timber.v("deviceCreationTs: $deviceCreationTs") + val eventRelativeAge = deviceCreationTs?.let { deviceTs -> + event.originServerTs?.let { + it - deviceTs + } + } + val failure = DecryptionFailure( + clock.epochMillis(), + roomId, + eventId, + error, + wasVisibleOnScreen = false, + ownIdentityTrustedAtTimeOfDecryptionFailure = isOwnIdentityTrusted, + isMatrixDotOrg = userHS == "matrix.org", + isFederated = messageSenderHs?.let { it != userHS }, + eventLocalAgeAtDecryptionFailure = eventRelativeAge + ) + Timber.v("Tracked failure: ${failure}") + trackedEventsMap[eventId] = failure + + if (currentTicker == null) { + rescheduleTicker() + } + } + + private fun handleEventDecrypted(eventId: String) { + Timber.v("Handle event decrypted $eventId time: ${clock.epochMillis()}") + // Only consider if it was tracked as a failure + val trackedFailure = trackedEventsMap[eventId] ?: return + + // Grace event if decrypted under 4s + val now = clock.epochMillis() + val timeToDecrypt = now - trackedFailure.timeStamp + Timber.v("Handle event decrypted timeToDecrypt: $timeToDecrypt for event $eventId") + if (timeToDecrypt < GRACE_PERIOD_MILLIS) { + Timber.v("Grace event $eventId") + trackedEventsMap.remove(eventId) + return + } + // We still want to report but with the time it took + if (trackedFailure.timeToDecryptMillis == null) { + val decryptionFailure = trackedFailure.copy(timeToDecryptMillis = timeToDecrypt) + trackedEventsMap[eventId] = decryptionFailure + reportFailure(decryptionFailure) + } + } + + fun utdDisplayedInTimeline(event: TimelineEvent) { + post { + // should be tracked (unless already reported) + val eventId = event.root.eventId ?: return@post + val trackedEvent = trackedEventsMap[eventId] ?: return@post + + trackedEventsMap[eventId] = trackedEvent.copy(wasVisibleOnScreen = true) + } + } + + // This will mutate the trackedEventsMap, so don't call it while iterating on it. + private fun reportFailure(decryptionFailure: DecryptionFailure) { + Timber.v("Report failure for event ${decryptionFailure.failedEventId}") + val error = decryptionFailure.toAnalyticsEvent() + val properties = decryptionFailure.toCustomProperties() + + Timber.v("capture error $error with properties $properties") + analyticsTracker.capture(error, properties) + + // now remove from tracked + trackedEventsMap.remove(decryptionFailure.failedEventId) + // mark as already reported + alreadyReported.add(decryptionFailure.failedEventId) } private fun checkFailures() { val now = clock.epochMillis() - val aggregatedErrors: Map> - synchronized(failures) { - val toReport = mutableListOf() - failures.removeAll { failure -> - (now - failure.timeStamp > GRACE_PERIOD_MILLIS).also { - if (it) { - toReport.add(failure) - } - } - } - - aggregatedErrors = toReport - .groupBy { it.error.toAnalyticsErrorName() } - .mapValues { - it.value.map { it.failedEventId } - } + Timber.v("Check failures now $now") + // report the definitely failed + val toReport = trackedEventsMap.values.filter { + now - it.timeStamp > MAX_WAIT_MILLIS } - - aggregatedErrors.forEach { aggregation -> - // there is now way to send the total/sum in posthog, so iterating - aggregation.value - // for now we ignore events already reported even if displayed again? - .filter { alreadyReported.contains(it).not() } - .forEach { failedEventId -> - analyticsTracker.capture(Error( - context = aggregation.key.first, - domain = Error.Domain.E2EE, - name = aggregation.key.second, - cryptoModule = currentModule - )) - alreadyReported.add(failedEventId) - } + toReport.forEach { + reportFailure( + it.copy(timeToDecryptMillis = -1) + ) } } - - private fun MXCryptoError.ErrorType.toAnalyticsErrorName(): DetailedErrorName { - val detailed = "$name | mxc_crypto_error_type" - val errorName = when (this) { - MXCryptoError.ErrorType.UNKNOWN_INBOUND_SESSION_ID, - MXCryptoError.ErrorType.KEYS_WITHHELD -> Error.Name.OlmKeysNotSentError - MXCryptoError.ErrorType.OLM -> Error.Name.OlmUnspecifiedError - MXCryptoError.ErrorType.UNKNOWN_MESSAGE_INDEX -> Error.Name.OlmIndexError - else -> Error.Name.UnknownError - } - return DetailedErrorName(detailed, errorName) - } } diff --git a/vector/src/main/java/im/vector/app/features/home/room/detail/TimelineViewModel.kt b/vector/src/main/java/im/vector/app/features/home/room/detail/TimelineViewModel.kt index 3793ed18d2..9e3802101e 100644 --- a/vector/src/main/java/im/vector/app/features/home/room/detail/TimelineViewModel.kt +++ b/vector/src/main/java/im/vector/app/features/home/room/detail/TimelineViewModel.kt @@ -1484,7 +1484,6 @@ class TimelineViewModel @AssistedInject constructor( override fun onCleared() { timeline?.dispose() timeline?.removeAllListeners() - decryptionFailureTracker.onTimeLineDisposed(initialState.roomId) if (vectorPreferences.sendTypingNotifs()) { room?.typingService()?.userStopsTyping() } diff --git a/vector/src/main/java/im/vector/app/features/home/room/detail/timeline/factory/TimelineItemFactory.kt b/vector/src/main/java/im/vector/app/features/home/room/detail/timeline/factory/TimelineItemFactory.kt index 84b71ceedf..3482eaf4ad 100644 --- a/vector/src/main/java/im/vector/app/features/home/room/detail/timeline/factory/TimelineItemFactory.kt +++ b/vector/src/main/java/im/vector/app/features/home/room/detail/timeline/factory/TimelineItemFactory.kt @@ -158,8 +158,8 @@ class TimelineItemFactory @Inject constructor( defaultItemFactory.create(params) } }.also { - if (it != null && event.isEncrypted()) { - decryptionFailureTracker.e2eEventDisplayedInTimeline(event) + if (it != null && event.isEncrypted() && event.root.mCryptoError != null) { + decryptionFailureTracker.utdDisplayedInTimeline(event) } } } diff --git a/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt b/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt new file mode 100644 index 0000000000..7f2f6e4c0b --- /dev/null +++ b/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt @@ -0,0 +1,617 @@ +/* + * Copyright (c) 2024 New Vector Ltd + * + * 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 im.vector.app.features.analytics + +import im.vector.app.features.analytics.plan.Error +import im.vector.app.test.fakes.FakeActiveSessionDataSource +import im.vector.app.test.fakes.FakeAnalyticsTracker +import im.vector.app.test.fakes.FakeClock +import im.vector.app.test.fakes.FakeSession +import im.vector.app.test.shared.createTimberTestRule +import io.mockk.every +import io.mockk.just +import io.mockk.mockk +import io.mockk.runs +import io.mockk.slot +import io.mockk.verify +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.ExperimentalCoroutinesApi +import kotlinx.coroutines.test.advanceTimeBy +import kotlinx.coroutines.test.runCurrent +import kotlinx.coroutines.test.runTest +import org.amshove.kluent.shouldBeEqualTo +import org.junit.Before +import org.junit.Rule +import org.junit.Test +import org.matrix.android.sdk.api.auth.LoginType +import org.matrix.android.sdk.api.auth.data.Credentials +import org.matrix.android.sdk.api.auth.data.SessionParams +import org.matrix.android.sdk.api.session.crypto.MXCryptoError +import org.matrix.android.sdk.api.session.crypto.model.CryptoDeviceInfo +import org.matrix.android.sdk.api.session.events.model.Event +import org.matrix.android.sdk.api.session.room.timeline.TimelineEvent +import java.text.SimpleDateFormat + +@ExperimentalCoroutinesApi +class DecryptionFailureTrackerTest { + + @Rule + fun timberTestRule() = createTimberTestRule() + + private val fakeAnalyticsTracker = FakeAnalyticsTracker() + + private val fakeActiveSessionDataSource = FakeActiveSessionDataSource() + + private val fakeClock = FakeClock() + + private val decryptionFailureTracker = DecryptionFailureTracker( + fakeAnalyticsTracker, + fakeActiveSessionDataSource.instance, + fakeClock + ) + + private val aCredential = Credentials( + userId = "@alice:matrix.org", + deviceId = "ABCDEFGHT", + homeServer = "http://matrix.org", + accessToken = "qwerty", + refreshToken = null, + ) + + private val fakeMxOrgTestSession = FakeSession().apply { + givenSessionParams( + SessionParams( + credentials = aCredential, + homeServerConnectionConfig = mockk(relaxed = true), + isTokenValid = true, + loginType = LoginType.PASSWORD + ) + ) + fakeUserId = "@alice:matrix.org" + } + + private val aUISIError = MXCryptoError.Base( + MXCryptoError.ErrorType.UNKNOWN_INBOUND_SESSION_ID, + "", + detailedErrorDescription = "" + ) + + private val aFakeBobMxOrgEvent = Event( + originServerTs = 90_000, + eventId = "$000", + senderId = "@bob:matrix.org", + roomId = "!roomA" + ) + + @Before + fun setupTest() { + fakeMxOrgTestSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(false) + } + + @Test + fun `should report late decryption to analytics tracker`() = runTest { + val fakeSession = fakeMxOrgTestSession + + every { + fakeAnalyticsTracker.capture(any(), any()) + } just runs + + fakeClock.givenEpoch(100_000) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(true) + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + // advance time by 5 seconds + fakeClock.givenEpoch(105_000) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + // it should report + verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + + verify { + fakeAnalyticsTracker.capture( + Error( + "mxc_crypto_error_type|", + Error.CryptoModule.Rust, + Error.Domain.E2EE, + Error.Name.OlmKeysNotSentError + ), + any() + ) + } + + // Can't do that in @Before function, it wont work as test will fail with: + // "the test coroutine is not completing, there were active child jobs" + // as the decryptionFailureTracker is setup to use the current test coroutine scope (?) + decryptionFailureTracker.stop() + } + + @Test + fun `should not report graced late decryption to analytics tracker`() = runTest { + val fakeSession = fakeMxOrgTestSession + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + + runCurrent() + // advance time by 3 seconds + currentFakeTime += 3_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted( + event, + emptyMap() + ) + + runCurrent() + + // it should not have reported it + verify(exactly = 0) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should report time to decrypt for late decryption`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(true) + + val event = aFakeBobMxOrgEvent + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + + runCurrent() + // advance time by 7 seconds, to be ahead of the 3 seconds grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted( + event, + emptyMap() + ) + + runCurrent() + + // it should report + verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + + val properties = propertiesSlot.captured + properties["timeToDecryptMillis"] shouldBeEqualTo 7000L + + decryptionFailureTracker.stop() + } + + @Test + fun `should report isMatrixDotOrg`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + propertiesSlot.captured["isMatrixDotOrg"] shouldBeEqualTo true + + val otherSession = FakeSession().apply { + givenSessionParams( + SessionParams( + credentials = aCredential.copy(userId = "@alice:another.org"), + homeServerConnectionConfig = mockk(relaxed = true), + isTokenValid = true, + loginType = LoginType.PASSWORD + ) + ) + every { sessionId } returns "WWEERE" + fakeUserId = "@alice:another.org" + this.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(true) + } + fakeActiveSessionDataSource.setActiveSession(otherSession) + runCurrent() + + val event2 = aFakeBobMxOrgEvent.copy(eventId = "$001") + + decryptionFailureTracker.onEventDecryptionError(event2, aUISIError) + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) + runCurrent() + + propertiesSlot.captured["isMatrixDotOrg"] shouldBeEqualTo false + + decryptionFailureTracker.stop() + } + + @Test + fun `should report if user trusted it's identity at time of decryption`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(false) + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(true) + val event2 = aFakeBobMxOrgEvent.copy(eventId = "$001") + decryptionFailureTracker.onEventDecryptionError(event2, aUISIError) + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + propertiesSlot.captured["userTrustsOwnIdentity"] shouldBeEqualTo false + + decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) + runCurrent() + + propertiesSlot.captured["userTrustsOwnIdentity"] shouldBeEqualTo true + + verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should not report same event twice`() = runTest { + val fakeSession = fakeMxOrgTestSession + + every { + fakeAnalyticsTracker.capture(any(), any()) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + + runCurrent() + + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should report if isFedrated`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + val event2 = aFakeBobMxOrgEvent.copy( + eventId = "$001", + senderId = "@bob:another.org", + ) + decryptionFailureTracker.onEventDecryptionError(event2, aUISIError) + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + propertiesSlot.captured["isFederated"] shouldBeEqualTo false + + decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) + runCurrent() + + propertiesSlot.captured["isFederated"] shouldBeEqualTo true + + verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should report if wasVisibleToUser`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + val event2 = aFakeBobMxOrgEvent.copy( + eventId = "$001", + senderId = "@bob:another.org", + ) + decryptionFailureTracker.onEventDecryptionError(event2, aUISIError) + runCurrent() + + decryptionFailureTracker.utdDisplayedInTimeline( + mockk(relaxed = true).apply { + every { root } returns event2 + every { eventId } returns event2.eventId.orEmpty() + } + ) + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate it's decrypted + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + propertiesSlot.captured["wasVisibleToUser"] shouldBeEqualTo false + + decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) + runCurrent() + + propertiesSlot.captured["wasVisibleToUser"] shouldBeEqualTo true + + verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should report if event relative age to session`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + val formatter = SimpleDateFormat("yyyy-MM-dd HH:mm:ss") + val historicalEventTimestamp = formatter.parse("2024-03-08 09:24:11")!!.time + val sessionCreationTime = formatter.parse("2024-03-09 10:00:00")!!.time + // 1mn after creation + val liveEventTimestamp = formatter.parse("2024-03-09 10:01:00")!!.time + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + fakeSession.fakeCryptoService.cryptoDeviceInfo = CryptoDeviceInfo( + deviceId = "ABCDEFGHT", + userId = "@alice:matrix.org", + firstTimeSeenLocalTs = sessionCreationTime + ) + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent.copy( + originServerTs = historicalEventTimestamp + ) + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + val liveEvent = aFakeBobMxOrgEvent.copy( + eventId = "$001", + originServerTs = liveEventTimestamp + ) + decryptionFailureTracker.onEventDecryptionError(liveEvent, aUISIError) + runCurrent() + + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + + // Now simulate historical event late decrypt + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) + runCurrent() + + propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo (historicalEventTimestamp - sessionCreationTime) + + decryptionFailureTracker.onEventDecrypted(liveEvent, emptyMap()) + runCurrent() + + propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo (liveEventTimestamp - sessionCreationTime) + propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo 60 * 1000L + + verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } + + @Test + fun `should report if permanent UTD`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val event = aFakeBobMxOrgEvent + + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + currentFakeTime += 70_000 + fakeClock.givenEpoch(currentFakeTime) + advanceTimeBy(70_000) + runCurrent() + + verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + + propertiesSlot.captured["timeToDecryptMillis"] shouldBeEqualTo -1L + decryptionFailureTracker.stop() + } + + @Test + fun `with multiple UTD`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val propertiesSlot = slot>() + + every { + fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + } just runs + + var currentFakeTime = 100_000L + fakeClock.givenEpoch(currentFakeTime) + fakeActiveSessionDataSource.setActiveSession(fakeSession) + decryptionFailureTracker.start(CoroutineScope(coroutineContext)) + runCurrent() + + val events = (0..10).map { + aFakeBobMxOrgEvent.copy( + eventId = "000$it", + originServerTs = 50_000 + it * 1000L + ) + } + + events.forEach { + decryptionFailureTracker.onEventDecryptionError(it, aUISIError) + } + runCurrent() + + currentFakeTime += 70_000 + fakeClock.givenEpoch(currentFakeTime) + advanceTimeBy(70_000) + runCurrent() + + verify(exactly = 11) { fakeAnalyticsTracker.capture(any(), any()) } + + decryptionFailureTracker.stop() + } +} diff --git a/vector/src/test/java/im/vector/app/test/fakes/FakeSession.kt b/vector/src/test/java/im/vector/app/test/fakes/FakeSession.kt index 12da88d286..9c791305b6 100644 --- a/vector/src/test/java/im/vector/app/test/fakes/FakeSession.kt +++ b/vector/src/test/java/im/vector/app/test/fakes/FakeSession.kt @@ -53,7 +53,10 @@ class FakeSession( mockkStatic("im.vector.app.core.extensions.SessionKt") } - override val myUserId: String = "@fake:server.fake" + var fakeUserId = "@fake:server.fake" + + override val myUserId: String + get() = fakeUserId override val coroutineDispatchers = testCoroutineDispatchers diff --git a/vector/src/test/java/im/vector/app/test/fakes/FakeUri.kt b/vector/src/test/java/im/vector/app/test/fakes/FakeUri.kt index 08bfac8db1..e24f14294e 100644 --- a/vector/src/test/java/im/vector/app/test/fakes/FakeUri.kt +++ b/vector/src/test/java/im/vector/app/test/fakes/FakeUri.kt @@ -28,6 +28,7 @@ class FakeUri(contentEquals: String? = null) { contentEquals?.let { givenEquals(it) every { instance.toString() } returns it + every { instance.scheme } returns contentEquals.substring(0, contentEquals.indexOf(':')) } }