From 3fa3eb11298543006d8e9de983dfa670e5215b48 Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 10:54:31 +0100 Subject: [PATCH 01/11] fix rust device to CryptoDeviceInfo mapping --- .../matrix/android/sdk/internal/crypto/Device.kt | 2 -- .../android/sdk/internal/crypto/OlmMachine.kt | 14 +++++++++----- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/Device.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/Device.kt index 0bd6ed06d1c..d2865f0f65f 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/Device.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/Device.kt @@ -172,8 +172,6 @@ internal class Device @AssistedInject constructor( * This will not fetch out fresh data from the Rust side. **/ internal fun toCryptoDeviceInfo(): CryptoDeviceInfo { -// val keys = innerDevice.keys.map { (keyId, key) -> keyId to key }.toMap() - return CryptoDeviceInfo( deviceId = innerDevice.deviceId, userId = innerDevice.userId, diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/OlmMachine.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/OlmMachine.kt index f90ae4a3452..4fe59fb1dde 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/OlmMachine.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/OlmMachine.kt @@ -189,18 +189,21 @@ internal class OlmMachine @Inject constructor( is OwnUserIdentity -> ownIdentity.trustsOurOwnDevice() else -> false } + val ownDevice = inner.getDevice(userId(), deviceId, 0u)!! + val creationTime = ownDevice.firstTimeSeenTs.toLong() return CryptoDeviceInfo( deviceId(), userId(), - // TODO pass the algorithms here. - listOf(), + ownDevice.algorithms, keys, mapOf(), - UnsignedDeviceInfo(), + UnsignedDeviceInfo( + deviceDisplayName = ownDevice.displayName + ), DeviceTrustLevel(crossSigningVerified, locallyVerified = true), false, - null + creationTime ) } @@ -291,7 +294,7 @@ internal class OlmMachine @Inject constructor( // checking the returned to devices to check for room keys. // XXX Anyhow there is now proper signaling we should soon stop parsing them manually receiveSyncChanges.toDeviceEvents.map { - outAdapter.fromJson(it) ?: Event() + outAdapter.fromJson(it) ?: Event() } } @@ -882,6 +885,7 @@ internal class OlmMachine @Inject constructor( inner.queryMissingSecretsFromOtherSessions() } } + @Throws(CryptoStoreException::class) suspend fun enableBackupV1(key: String, version: String) { return withContext(coroutineDispatchers.computation) { From 72d2199f1ae226e3503629b0172833181796a267 Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 11:04:35 +0100 Subject: [PATCH 02/11] refactor: StreamEventsManager report MXCryptoError instead of throwable --- .../org/matrix/android/sdk/api/session/LiveEventListener.kt | 3 ++- .../matrix/android/sdk/internal/session/StreamEventsManager.kt | 3 ++- vector/src/main/java/im/vector/app/UISIDetector.kt | 3 ++- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/LiveEventListener.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/LiveEventListener.kt index b4b283c86a2..ce0a01a4918 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/LiveEventListener.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/LiveEventListener.kt @@ -16,6 +16,7 @@ package org.matrix.android.sdk.api.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.util.JsonDict @@ -27,7 +28,7 @@ interface LiveEventListener { fun onEventDecrypted(event: Event, clearEvent: JsonDict) - fun onEventDecryptionError(event: Event, throwable: Throwable) + fun onEventDecryptionError(event: Event, cryptoError: MXCryptoError) fun onLiveToDeviceEvent(event: Event) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/StreamEventsManager.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/StreamEventsManager.kt index ce34b0430ec..3e7beed0472 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/StreamEventsManager.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/StreamEventsManager.kt @@ -22,6 +22,7 @@ import kotlinx.coroutines.SupervisorJob import kotlinx.coroutines.launch import org.matrix.android.sdk.api.extensions.tryOrNull import org.matrix.android.sdk.api.session.LiveEventListener +import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.crypto.model.MXEventDecryptionResult import org.matrix.android.sdk.api.session.events.model.Event import timber.log.Timber @@ -75,7 +76,7 @@ internal class StreamEventsManager @Inject constructor() { } } - fun dispatchLiveEventDecryptionFailed(event: Event, error: Throwable) { + fun dispatchLiveEventDecryptionFailed(event: Event, error: MXCryptoError) { Timber.v("## dispatchLiveEventDecryptionFailed ${event.eventId}") coroutineScope.launch { listeners.forEach { diff --git a/vector/src/main/java/im/vector/app/UISIDetector.kt b/vector/src/main/java/im/vector/app/UISIDetector.kt index 4a9d8ae266c..7188fb0dc93 100644 --- a/vector/src/main/java/im/vector/app/UISIDetector.kt +++ b/vector/src/main/java/im/vector/app/UISIDetector.kt @@ -18,6 +18,7 @@ package im.vector.app import org.matrix.android.sdk.api.extensions.orFalse import org.matrix.android.sdk.api.session.LiveEventListener +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.events.model.content.EncryptedEventContent import org.matrix.android.sdk.api.session.events.model.toModel @@ -84,7 +85,7 @@ class UISIDetector(private val timeoutMillis: Long = 30_000L) : LiveEventListene } } - override fun onEventDecryptionError(event: Event, throwable: Throwable) { + override fun onEventDecryptionError(event: Event, cryptoError: MXCryptoError) { val eventId = event.eventId val roomId = event.roomId if (!enabled || eventId == null || roomId == null) return From 1f430a40159718859a5791922fb8728270faddcd Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 11:25:44 +0100 Subject: [PATCH 03/11] Analytics tracker, support report custom properties not yet in schame --- .../im/vector/app/features/analytics/AnalyticsTracker.kt | 4 +++- .../app/features/analytics/impl/DefaultVectorAnalytics.kt | 8 ++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt b/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt index 871782e473c..669202dcbb4 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt @@ -23,8 +23,10 @@ import im.vector.app.features.analytics.plan.UserProperties interface AnalyticsTracker { /** * Capture an Event. + * + * @param customProperties Some custom properties to attach to the event. */ - fun capture(event: VectorAnalyticsEvent) + fun capture(event: VectorAnalyticsEvent, customProperties: Map? = null) /** * Track a displayed screen. diff --git a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt index 2a7d0ac975f..ff80c81ec73 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt @@ -171,11 +171,15 @@ class DefaultVectorAnalytics @Inject constructor( } } - override fun capture(event: VectorAnalyticsEvent) { + override fun capture(event: VectorAnalyticsEvent, customProperties: Map?) { Timber.tag(analyticsTag.value).d("capture($event)") posthog ?.takeIf { userConsent == true } - ?.capture(event.getName(), event.getProperties()?.toPostHogProperties()) + ?.capture( + event.getName(), + (customProperties.orEmpty() + + event.getProperties().orEmpty()).toPostHogProperties() + ) } override fun screen(screen: VectorAnalyticsScreen) { From fcc5181a2862a5dfff1c5f74731bad9d5ee2bd4f Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 11:26:36 +0100 Subject: [PATCH 04/11] 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 | 309 ++++++--- .../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, 925 insertions(+), 99 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 7b41c127736..fe4cc3311b0 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 472d0896f9a..5523c849944 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 00000000000..034b4cbcc30 --- /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 d596741d532..53c5d87770a 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 { + + // 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() - private val scope: CoroutineScope = CoroutineScope(SupervisorJob()) - private val failures = mutableListOf() + // 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) + } + } - private fun addDecryptionFailure(failure: DecryptionFailure) { - // de duplicate - synchronized(failures) { - if (failures.none { it.failedEventId == failure.failedEventId }) { - failures.add(failure) + // LiveEventListener callbacks + + override fun onEventDecrypted(event: Event, clearEvent: JsonDict) { + Timber.v("Event decrypted ${event.eventId}") + event.eventId?.let { + post { + handleEventDecrypted(it) } } } - private fun removeFailureForEventId(eventId: String) { - synchronized(failures) { - failures.removeIfCompat { it.failedEventId == eventId } + 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 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) - } - } + 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 - aggregatedErrors = toReport - .groupBy { it.error.toAnalyticsErrorName() } - .mapValues { - it.value.map { it.failedEventId } - } + if (currentTicker == null) { + rescheduleTicker() } + } - 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) - } + 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) } } - 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 + 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() + Timber.v("Check failures now $now") + // report the definitely failed + val toReport = trackedEventsMap.values.filter { + now - it.timeStamp > MAX_WAIT_MILLIS + } + toReport.forEach { + reportFailure( + it.copy(timeToDecryptMillis = -1) + ) } - 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 3793ed18d2e..9e3802101eb 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 84b71ceedfc..3482eaf4ad2 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 00000000000..7f2f6e4c0b1 --- /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 12da88d286c..9c791305b6a 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 08bfac8db15..e24f14294ec 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(':')) } } From 28eead74cb72c30f7fa53e00862c06d1cd12e71e Mon Sep 17 00:00:00 2001 From: Valere Date: Thu, 14 Mar 2024 11:35:34 +0100 Subject: [PATCH 05/11] doc update --- .../java/im/vector/app/features/analytics/DecryptionFailure.kt | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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 index 034b4cbcc30..f6134e291ba 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt @@ -26,7 +26,8 @@ data class DecryptionFailure( val error: MXCryptoError, val wasVisibleOnScreen: Boolean, val ownIdentityTrustedAtTimeOfDecryptionFailure: Boolean, - // If this is set, it means that the event was decrypted but late + // If this is set, it means that the event was decrypted but late. Will be -1 if + // the event was not decrypted after the maximum wait time. val timeToDecryptMillis: Long? = null, val isMatrixDotOrg: Boolean, val isFederated: Boolean? = null, From 4d04b276ffa7431a95844eea0af6eb11bd6b69bd Mon Sep 17 00:00:00 2001 From: Valere Date: Wed, 27 Mar 2024 10:49:08 +0100 Subject: [PATCH 06/11] use the new updated analytics events --- .../features/analytics/AnalyticsTracker.kt | 4 +- .../features/analytics/DecryptionFailure.kt | 28 ++--- .../analytics/DecryptionFailureTracker.kt | 4 +- .../analytics/impl/DefaultVectorAnalytics.kt | 5 +- .../analytics/DecryptionFailureTrackerTest.kt | 107 +++++++++--------- 5 files changed, 67 insertions(+), 81 deletions(-) diff --git a/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt b/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt index 669202dcbb4..871782e473c 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/AnalyticsTracker.kt @@ -23,10 +23,8 @@ import im.vector.app.features.analytics.plan.UserProperties interface AnalyticsTracker { /** * Capture an Event. - * - * @param customProperties Some custom properties to attach to the event. */ - fun capture(event: VectorAnalyticsEvent, customProperties: Map? = null) + fun capture(event: VectorAnalyticsEvent) /** * Track a displayed screen. 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 index f6134e291ba..6dd45c570e7 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt @@ -41,29 +41,17 @@ fun DecryptionFailure.toAnalyticsEvent(): Error { domain = Error.Domain.E2EE, name = this.error.toAnalyticsErrorName(), // this is deprecated keep for backward compatibility - cryptoModule = Error.CryptoModule.Rust + cryptoModule = Error.CryptoModule.Rust, + cryptoSDK = Error.CryptoSDK.Rust, + eventLocalAgeMillis = eventLocalAgeAtDecryptionFailure?.toInt(), + isFederated = isFederated, + isMatrixDotOrg = isMatrixDotOrg, + timeToDecryptMillis = timeToDecryptMillis?.toInt() ?: -1, + wasVisibleToUser = wasVisibleOnScreen, + userTrustsOwnIdentity = ownIdentityTrustedAtTimeOfDecryptionFailure, ) } -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) { 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 53c5d87770a..f96d8a82626 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 @@ -268,10 +268,8 @@ class DecryptionFailureTracker @Inject constructor( 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) + analyticsTracker.capture(error) // now remove from tracked trackedEventsMap.remove(decryptionFailure.failedEventId) diff --git a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt index ff80c81ec73..d4f34ffaf29 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt @@ -171,14 +171,13 @@ class DefaultVectorAnalytics @Inject constructor( } } - override fun capture(event: VectorAnalyticsEvent, customProperties: Map?) { + override fun capture(event: VectorAnalyticsEvent) { Timber.tag(analyticsTag.value).d("capture($event)") posthog ?.takeIf { userConsent == true } ?.capture( event.getName(), - (customProperties.orEmpty() + - event.getProperties().orEmpty()).toPostHogProperties() + event.getProperties().orEmpty().toPostHogProperties() ) } 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 index 7f2f6e4c0b1..6088d2c465c 100644 --- a/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt +++ b/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt @@ -16,6 +16,7 @@ package im.vector.app.features.analytics +import im.vector.app.features.analytics.itf.VectorAnalyticsEvent import im.vector.app.features.analytics.plan.Error import im.vector.app.test.fakes.FakeActiveSessionDataSource import im.vector.app.test.fakes.FakeAnalyticsTracker @@ -107,7 +108,7 @@ class DecryptionFailureTrackerTest { val fakeSession = fakeMxOrgTestSession every { - fakeAnalyticsTracker.capture(any(), any()) + fakeAnalyticsTracker.capture(any()) } just runs fakeClock.givenEpoch(100_000) @@ -129,17 +130,22 @@ class DecryptionFailureTrackerTest { runCurrent() // it should report - verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } verify { fakeAnalyticsTracker.capture( - Error( + im.vector.app.features.analytics.plan.Error( "mxc_crypto_error_type|", - Error.CryptoModule.Rust, - Error.Domain.E2EE, - Error.Name.OlmKeysNotSentError + cryptoModule = Error.CryptoModule.Rust, + domain = Error.Domain.E2EE, + name = Error.Name.OlmKeysNotSentError, + cryptoSDK = Error.CryptoSDK.Rust, + timeToDecryptMillis = 5000, + isFederated = false, + isMatrixDotOrg = true, + userTrustsOwnIdentity = true, + wasVisibleToUser = false ), - any() ) } @@ -177,7 +183,7 @@ class DecryptionFailureTrackerTest { runCurrent() // it should not have reported it - verify(exactly = 0) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 0) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -186,10 +192,10 @@ class DecryptionFailureTrackerTest { fun `should report time to decrypt for late decryption`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs var currentFakeTime = 100_000L @@ -217,10 +223,10 @@ class DecryptionFailureTrackerTest { runCurrent() // it should report - verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } - val properties = propertiesSlot.captured - properties["timeToDecryptMillis"] shouldBeEqualTo 7000L + val error = eventSlot.captured as Error + error.timeToDecryptMillis shouldBeEqualTo 7000 decryptionFailureTracker.stop() } @@ -229,10 +235,10 @@ class DecryptionFailureTrackerTest { fun `should report isMatrixDotOrg`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs var currentFakeTime = 100_000L @@ -254,7 +260,8 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - propertiesSlot.captured["isMatrixDotOrg"] shouldBeEqualTo true + val error = eventSlot.captured as Error + error.isMatrixDotOrg shouldBeEqualTo true val otherSession = FakeSession().apply { givenSessionParams( @@ -285,7 +292,7 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) runCurrent() - propertiesSlot.captured["isMatrixDotOrg"] shouldBeEqualTo false + (eventSlot.captured as Error).isMatrixDotOrg shouldBeEqualTo false decryptionFailureTracker.stop() } @@ -294,10 +301,10 @@ class DecryptionFailureTrackerTest { fun `should report if user trusted it's identity at time of decryption`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs var currentFakeTime = 100_000L @@ -325,14 +332,14 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - propertiesSlot.captured["userTrustsOwnIdentity"] shouldBeEqualTo false + (eventSlot.captured as Error).userTrustsOwnIdentity shouldBeEqualTo false decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) runCurrent() - propertiesSlot.captured["userTrustsOwnIdentity"] shouldBeEqualTo true + (eventSlot.captured as Error).userTrustsOwnIdentity shouldBeEqualTo true - verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -342,7 +349,7 @@ class DecryptionFailureTrackerTest { val fakeSession = fakeMxOrgTestSession every { - fakeAnalyticsTracker.capture(any(), any()) + fakeAnalyticsTracker.capture(any()) } just runs var currentFakeTime = 100_000L @@ -365,7 +372,7 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.onEventDecryptionError(event, aUISIError) @@ -374,7 +381,7 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -383,10 +390,10 @@ class DecryptionFailureTrackerTest { fun `should report if isFedrated`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs var currentFakeTime = 100_000L @@ -415,14 +422,14 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - propertiesSlot.captured["isFederated"] shouldBeEqualTo false + (eventSlot.captured as Error).isFederated shouldBeEqualTo false decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) runCurrent() - propertiesSlot.captured["isFederated"] shouldBeEqualTo true + (eventSlot.captured as Error).isFederated shouldBeEqualTo true - verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -430,13 +437,11 @@ class DecryptionFailureTrackerTest { @Test fun `should report if wasVisibleToUser`() = runTest { val fakeSession = fakeMxOrgTestSession - - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs - var currentFakeTime = 100_000L fakeClock.givenEpoch(currentFakeTime) fakeActiveSessionDataSource.setActiveSession(fakeSession) @@ -470,14 +475,14 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - propertiesSlot.captured["wasVisibleToUser"] shouldBeEqualTo false + (eventSlot.captured as Error).wasVisibleToUser shouldBeEqualTo false decryptionFailureTracker.onEventDecrypted(event2, emptyMap()) runCurrent() - propertiesSlot.captured["wasVisibleToUser"] shouldBeEqualTo true + (eventSlot.captured as Error).wasVisibleToUser shouldBeEqualTo true - verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -486,16 +491,16 @@ class DecryptionFailureTrackerTest { 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 + val eventSlot = slot() + every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs fakeSession.fakeCryptoService.cryptoDeviceInfo = CryptoDeviceInfo( @@ -532,15 +537,15 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() - propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo (historicalEventTimestamp - sessionCreationTime) + (eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo (historicalEventTimestamp - sessionCreationTime).toInt() decryptionFailureTracker.onEventDecrypted(liveEvent, emptyMap()) runCurrent() - propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo (liveEventTimestamp - sessionCreationTime) - propertiesSlot.captured["eventLocalAgeAtDecryptionFailure"] shouldBeEqualTo 60 * 1000L + (eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo (liveEventTimestamp - sessionCreationTime).toInt() + (eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo 60 * 1000 - verify(exactly = 2) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } @@ -549,10 +554,10 @@ class DecryptionFailureTrackerTest { fun `should report if permanent UTD`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() + val eventSlot = slot() every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(event = capture(eventSlot)) } just runs var currentFakeTime = 100_000L @@ -571,9 +576,9 @@ class DecryptionFailureTrackerTest { advanceTimeBy(70_000) runCurrent() - verify(exactly = 1) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } - propertiesSlot.captured["timeToDecryptMillis"] shouldBeEqualTo -1L + (eventSlot.captured as Error).timeToDecryptMillis shouldBeEqualTo -1 decryptionFailureTracker.stop() } @@ -581,10 +586,8 @@ class DecryptionFailureTrackerTest { fun `with multiple UTD`() = runTest { val fakeSession = fakeMxOrgTestSession - val propertiesSlot = slot>() - every { - fakeAnalyticsTracker.capture(any(), customProperties = capture(propertiesSlot)) + fakeAnalyticsTracker.capture(any()) } just runs var currentFakeTime = 100_000L @@ -610,7 +613,7 @@ class DecryptionFailureTrackerTest { advanceTimeBy(70_000) runCurrent() - verify(exactly = 11) { fakeAnalyticsTracker.capture(any(), any()) } + verify(exactly = 11) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.stop() } From 9ebc10f4c2b39a441690d215aec83510110da04a Mon Sep 17 00:00:00 2001 From: Valere Date: Wed, 27 Mar 2024 11:31:12 +0100 Subject: [PATCH 07/11] KDoc punctuation --- .../vector/app/features/analytics/DecryptionFailureTracker.kt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 f96d8a82626..613daf3ded1 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 @@ -89,7 +89,7 @@ class DecryptionFailureTracker @Inject constructor( private var currentTicker: Job? = null /** - * Start the tracker + * Start the tracker. * * @param scope The coroutine scope to use, exposed for tests. If null, it will use the default one */ From 393f3f30309aebf7395f0e6eeb93cd743d15a800 Mon Sep 17 00:00:00 2001 From: Valere Date: Wed, 27 Mar 2024 11:59:21 +0100 Subject: [PATCH 08/11] Use new error name for expected UTD --- .../features/analytics/DecryptionFailure.kt | 17 ++- .../analytics/DecryptionFailureTrackerTest.kt | 137 ++++++++++++++++++ 2 files changed, 150 insertions(+), 4 deletions(-) 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 index 6dd45c570e7..f7fb177e12c 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/DecryptionFailure.kt @@ -39,7 +39,7 @@ fun DecryptionFailure.toAnalyticsEvent(): Error { return Error( context = "mxc_crypto_error_type|${errorMsg}", domain = Error.Domain.E2EE, - name = this.error.toAnalyticsErrorName(), + name = this.toAnalyticsErrorName(), // this is deprecated keep for backward compatibility cryptoModule = Error.CryptoModule.Rust, cryptoSDK = Error.CryptoSDK.Rust, @@ -52,9 +52,10 @@ fun DecryptionFailure.toAnalyticsEvent(): Error { ) } -private fun MXCryptoError.toAnalyticsErrorName(): Error.Name { - return if (this is MXCryptoError.Base) { - when (errorType) { +private fun DecryptionFailure.toAnalyticsErrorName(): Error.Name { + val error = this.error + val name = if (error is MXCryptoError.Base) { + when (error.errorType) { MXCryptoError.ErrorType.UNKNOWN_INBOUND_SESSION_ID, MXCryptoError.ErrorType.KEYS_WITHHELD -> Error.Name.OlmKeysNotSentError MXCryptoError.ErrorType.OLM -> Error.Name.OlmUnspecifiedError @@ -64,4 +65,12 @@ private fun MXCryptoError.toAnalyticsErrorName(): Error.Name { } else { Error.Name.UnknownError } + // check if it's an expected UTD! + val localAge = this.eventLocalAgeAtDecryptionFailure + val isHistorical = localAge != null && localAge < 0 + if (isHistorical && !this.ownIdentityTrustedAtTimeOfDecryptionFailure) { + return Error.Name.HistoricalMessage + } + + return name } 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 index 6088d2c465c..3be9a6dd182 100644 --- a/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt +++ b/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt @@ -35,6 +35,7 @@ import kotlinx.coroutines.test.advanceTimeBy import kotlinx.coroutines.test.runCurrent import kotlinx.coroutines.test.runTest import org.amshove.kluent.shouldBeEqualTo +import org.amshove.kluent.shouldNotBeEqualTo import org.junit.Before import org.junit.Rule import org.junit.Test @@ -550,6 +551,142 @@ class DecryptionFailureTrackerTest { decryptionFailureTracker.stop() } + @Test + fun `should report historical UTDs as an expected UTD if not verified`() = runTest { + val fakeSession = fakeMxOrgTestSession + + 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 + + val eventSlot = slot() + + every { + fakeAnalyticsTracker.capture(event = capture(eventSlot)) + } 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() + + // historical event and session not verified + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(false) + val event = aFakeBobMxOrgEvent.copy( + originServerTs = historicalEventTimestamp + ) + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + // advance time to be ahead of the permanent UTD period + currentFakeTime += 70_000 + fakeClock.givenEpoch(currentFakeTime) + advanceTimeBy(70_000) + runCurrent() + + (eventSlot.captured as Error).name shouldBeEqualTo Error.Name.HistoricalMessage + + decryptionFailureTracker.stop() + } + + @Test + fun `should not report historical UTDs as an expected UTD if verified`() = runTest { + val fakeSession = fakeMxOrgTestSession + + 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 + + val eventSlot = slot() + + every { + fakeAnalyticsTracker.capture(event = capture(eventSlot)) + } 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() + + // historical event and session not verified + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(true) + val event = aFakeBobMxOrgEvent.copy( + originServerTs = historicalEventTimestamp + ) + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + // advance time to be ahead of the permanent UTD period + currentFakeTime += 70_000 + fakeClock.givenEpoch(currentFakeTime) + advanceTimeBy(70_000) + runCurrent() + + (eventSlot.captured as Error).name shouldNotBeEqualTo Error.Name.HistoricalMessage + + decryptionFailureTracker.stop() + } + + @Test + fun `should not report live UTDs as an expected UTD even if not verified`() = runTest { + val fakeSession = fakeMxOrgTestSession + + val formatter = SimpleDateFormat("yyyy-MM-dd HH:mm:ss") + 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 + + val eventSlot = slot() + + every { + fakeAnalyticsTracker.capture(event = capture(eventSlot)) + } 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() + + // historical event and session not verified + fakeSession.fakeCryptoService.fakeCrossSigningService.givenIsCrossSigningVerifiedReturns(false) + val event = aFakeBobMxOrgEvent.copy( + originServerTs = liveEventTimestamp + ) + decryptionFailureTracker.onEventDecryptionError(event, aUISIError) + runCurrent() + + // advance time to be ahead of the permanent UTD period + currentFakeTime += 70_000 + fakeClock.givenEpoch(currentFakeTime) + advanceTimeBy(70_000) + runCurrent() + + (eventSlot.captured as Error).name shouldNotBeEqualTo Error.Name.HistoricalMessage + + decryptionFailureTracker.stop() + } + @Test fun `should report if permanent UTD`() = runTest { val fakeSession = fakeMxOrgTestSession From 0f3f2b164eb035353b1c72ec51136bc3414ba320 Mon Sep 17 00:00:00 2001 From: Valere Date: Wed, 27 Mar 2024 12:00:53 +0100 Subject: [PATCH 09/11] add changelog --- changelog.d/8780.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/8780.misc diff --git a/changelog.d/8780.misc b/changelog.d/8780.misc new file mode 100644 index 00000000000..03253757559 --- /dev/null +++ b/changelog.d/8780.misc @@ -0,0 +1 @@ +Improve UTD reporting by adding additional fields to the report. From 2bbb49bdd3e85f10844844309ad1bf333a226e18 Mon Sep 17 00:00:00 2001 From: Valere Date: Tue, 2 Apr 2024 09:33:10 +0200 Subject: [PATCH 10/11] Fix: should remember already reported events --- .../app/features/analytics/DecryptionFailureTracker.kt | 4 ++++ .../app/features/analytics/DecryptionFailureTrackerTest.kt | 5 ++++- 2 files changed, 8 insertions(+), 1 deletion(-) 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 613daf3ded1..fcbc67169eb 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 @@ -201,6 +201,10 @@ class DecryptionFailureTracker @Inject constructor( // already tracked return } + if (alreadyReported.contains(eventId)) { + // already reported + return + } val isOwnIdentityTrusted = session.cryptoService().crossSigningService().isCrossSigningVerified() val userHS = MatrixPatterns.extractServerNameFromId(session.myUserId) val messageSenderHs = event.senderId?.let { MatrixPatterns.extractServerNameFromId(it) } 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 index 3be9a6dd182..2f11d4c2eb1 100644 --- a/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt +++ b/vector/src/test/java/im/vector/app/features/analytics/DecryptionFailureTrackerTest.kt @@ -376,9 +376,12 @@ class DecryptionFailureTrackerTest { verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) } decryptionFailureTracker.onEventDecryptionError(event, aUISIError) - runCurrent() + // advance time by 7 seconds, to be ahead of the grace period + currentFakeTime += 7_000 + fakeClock.givenEpoch(currentFakeTime) + decryptionFailureTracker.onEventDecrypted(event, emptyMap()) runCurrent() From 752c884eaaf2c4a3aa4efff7fc2f62819a28fa15 Mon Sep 17 00:00:00 2001 From: Valere Date: Tue, 2 Apr 2024 11:44:05 +0200 Subject: [PATCH 11/11] Analytics | if no property use null instead of empty map --- .../app/features/analytics/impl/DefaultVectorAnalytics.kt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt index d4f34ffaf29..acc6ebf51e8 100644 --- a/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt +++ b/vector/src/main/java/im/vector/app/features/analytics/impl/DefaultVectorAnalytics.kt @@ -177,7 +177,7 @@ class DefaultVectorAnalytics @Inject constructor( ?.takeIf { userConsent == true } ?.capture( event.getName(), - event.getProperties().orEmpty().toPostHogProperties() + event.getProperties()?.toPostHogProperties() ) }