Merge pull request #8780 from element-hq/valere/utd_posthog_more_properties

UTD posthog reporting add more properties to captured event
This commit is contained in:
Valere 2024-04-02 15:03:14 +02:00 committed by GitHub
commit 0f3ff2ed45
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
16 changed files with 1093 additions and 115 deletions

1
changelog.d/8780.misc Normal file
View file

@ -0,0 +1 @@
Improve UTD reporting by adding additional fields to the report.

View file

@ -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)

View file

@ -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,

View file

@ -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) {

View file

@ -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 {

View file

@ -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

View file

@ -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

View file

@ -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() {

View file

@ -0,0 +1,76 @@
/*
* 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. 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,
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.toAnalyticsErrorName(),
// this is deprecated keep for backward compatibility
cryptoModule = Error.CryptoModule.Rust,
cryptoSDK = Error.CryptoSDK.Rust,
eventLocalAgeMillis = eventLocalAgeAtDecryptionFailure?.toInt(),
isFederated = isFederated,
isMatrixDotOrg = isMatrixDotOrg,
timeToDecryptMillis = timeToDecryptMillis?.toInt() ?: -1,
wasVisibleToUser = wasVisibleOnScreen,
userTrustsOwnIdentity = ownIdentityTrustedAtTimeOfDecryptionFailure,
)
}
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
MXCryptoError.ErrorType.UNKNOWN_MESSAGE_INDEX -> Error.Name.OlmIndexError
else -> Error.Name.UnknownError
}
} 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
}

View file

@ -16,149 +16,282 @@
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<String, Error.Name>
// 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<DecryptionFailure>()
// 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<String, DecryptionFailure>()
// List of eventId that have been reported, to avoid double reporting
private val alreadyReported = mutableListOf<String>()
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
}
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) }
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()
analyticsTracker.capture(error)
// 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<DetailedErrorName, List<String>>
synchronized(failures) {
val toReport = mutableListOf<DecryptionFailure>()
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)
}
}

View file

@ -175,7 +175,10 @@ class DefaultVectorAnalytics @Inject constructor(
Timber.tag(analyticsTag.value).d("capture($event)")
posthog
?.takeIf { userConsent == true }
?.capture(event.getName(), event.getProperties()?.toPostHogProperties())
?.capture(
event.getName(),
event.getProperties()?.toPostHogProperties()
)
}
override fun screen(screen: VectorAnalyticsScreen) {

View file

@ -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()
}

View file

@ -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)
}
}
}

View file

@ -0,0 +1,760 @@
/*
* 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.itf.VectorAnalyticsEvent
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.amshove.kluent.shouldNotBeEqualTo
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())
} 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()) }
verify {
fakeAnalyticsTracker.capture(
im.vector.app.features.analytics.plan.Error(
"mxc_crypto_error_type|",
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
),
)
}
// 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()) }
decryptionFailureTracker.stop()
}
@Test
fun `should report time to decrypt for late decryption`() = runTest {
val fakeSession = fakeMxOrgTestSession
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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()) }
val error = eventSlot.captured as Error
error.timeToDecryptMillis shouldBeEqualTo 7000
decryptionFailureTracker.stop()
}
@Test
fun `should report isMatrixDotOrg`() = runTest {
val fakeSession = fakeMxOrgTestSession
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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()
val error = eventSlot.captured as Error
error.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()
(eventSlot.captured as Error).isMatrixDotOrg shouldBeEqualTo false
decryptionFailureTracker.stop()
}
@Test
fun `should report if user trusted it's identity at time of decryption`() = runTest {
val fakeSession = fakeMxOrgTestSession
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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()
(eventSlot.captured as Error).userTrustsOwnIdentity shouldBeEqualTo false
decryptionFailureTracker.onEventDecrypted(event2, emptyMap())
runCurrent()
(eventSlot.captured as Error).userTrustsOwnIdentity shouldBeEqualTo true
verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) }
decryptionFailureTracker.stop()
}
@Test
fun `should not report same event twice`() = runTest {
val fakeSession = fakeMxOrgTestSession
every {
fakeAnalyticsTracker.capture(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()) }
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()
verify(exactly = 1) { fakeAnalyticsTracker.capture(any()) }
decryptionFailureTracker.stop()
}
@Test
fun `should report if isFedrated`() = runTest {
val fakeSession = fakeMxOrgTestSession
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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()
(eventSlot.captured as Error).isFederated shouldBeEqualTo false
decryptionFailureTracker.onEventDecrypted(event2, emptyMap())
runCurrent()
(eventSlot.captured as Error).isFederated shouldBeEqualTo true
verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) }
decryptionFailureTracker.stop()
}
@Test
fun `should report if wasVisibleToUser`() = runTest {
val fakeSession = fakeMxOrgTestSession
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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<TimelineEvent>(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()
(eventSlot.captured as Error).wasVisibleToUser shouldBeEqualTo false
decryptionFailureTracker.onEventDecrypted(event2, emptyMap())
runCurrent()
(eventSlot.captured as Error).wasVisibleToUser shouldBeEqualTo true
verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) }
decryptionFailureTracker.stop()
}
@Test
fun `should report if event relative age to session`() = 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
// 1mn after creation
val liveEventTimestamp = formatter.parse("2024-03-09 10:01:00")!!.time
val eventSlot = slot<VectorAnalyticsEvent>()
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()
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()
(eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo (historicalEventTimestamp - sessionCreationTime).toInt()
decryptionFailureTracker.onEventDecrypted(liveEvent, emptyMap())
runCurrent()
(eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo (liveEventTimestamp - sessionCreationTime).toInt()
(eventSlot.captured as Error).eventLocalAgeMillis shouldBeEqualTo 60 * 1000
verify(exactly = 2) { fakeAnalyticsTracker.capture(any()) }
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<VectorAnalyticsEvent>()
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<VectorAnalyticsEvent>()
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<VectorAnalyticsEvent>()
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
val eventSlot = slot<VectorAnalyticsEvent>()
every {
fakeAnalyticsTracker.capture(event = capture(eventSlot))
} 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()) }
(eventSlot.captured as Error).timeToDecryptMillis shouldBeEqualTo -1
decryptionFailureTracker.stop()
}
@Test
fun `with multiple UTD`() = runTest {
val fakeSession = fakeMxOrgTestSession
every {
fakeAnalyticsTracker.capture(any())
} 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()) }
decryptionFailureTracker.stop()
}
}

View file

@ -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

View file

@ -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(':'))
}
}