Fix tests and better logs

matrix-sdk-android/src/androidTest/java/org/matrix/android/sdk/internal/crypto/DecryptRedactedEventTest.kt

@@ -46,7 +46,7 @@ class DecryptRedactedEventTest : InstrumentedTest {
         roomALicePOV.sendService().redactEvent(timelineEvent.root, redactionReason)
 
         // get the event from bob
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff {
             bobSession.getRoom(e2eRoomID)?.getTimelineEvent(timelineEvent.eventId)?.root?.isRedacted() == true
         }
 

matrix-sdk-android/src/androidTest/java/org/matrix/android/sdk/internal/crypto/E2eeSanityTests.kt

@@ -101,7 +101,7 @@ class E2eeSanityTests : InstrumentedTest {
                         fail("${otherSession.myUserId.take(10)} should be able to decrypt")
                     }) {
                 val timeLineEvent = otherSession.getRoom(e2eRoomID)?.getTimelineEvent(sentEventId!!).also {
-                    Log.v("#E2E TEST", "Event seen by new user ${it?.root?.getClearType()}|${it?.root?.mCryptoError}")
+                    Log.v("#E2E TEST", "Event seen by new user ${it?.root?.getClearType()}|${it?.root?.mCryptoError}|${it?.root?.mxDecryptionResult?.isSafe}")
                 }
                 timeLineEvent != null &&
                         timeLineEvent.isEncrypted() &&

matrix-sdk-android/src/androidTest/java/org/matrix/android/sdk/internal/crypto/E2eeShareKeysHistoryTest.kt

@@ -18,6 +18,7 @@ package org.matrix.android.sdk.internal.crypto
 
 import android.util.Log
 import androidx.test.filters.LargeTest
+import org.amshove.kluent.fail
 import org.amshove.kluent.internal.assertEquals
 import org.amshove.kluent.internal.assertNotEquals
 import org.junit.Assert
@@ -42,7 +43,6 @@ import org.matrix.android.sdk.api.session.room.model.shouldShareHistory
 import org.matrix.android.sdk.common.CommonTestHelper
 import org.matrix.android.sdk.common.CommonTestHelper.Companion.runCryptoTest
 import org.matrix.android.sdk.common.SessionTestParams
-import org.matrix.android.sdk.common.wrapWithTimeout
 
 @RunWith(JUnit4::class)
 @FixMethodOrder(MethodSorters.JVM)
@@ -99,11 +99,17 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
 
                 val aliceMessageId: String? = sendMessageInRoom(aliceRoomPOV, aliceMessageText, testHelper)
                 Assert.assertTrue("Message should be sent", aliceMessageId != null)
-                Log.v("#E2E TEST", "Alice sent message to roomId: $e2eRoomID")
+                Log.v("#E2E TEST", "Alice has sent message to roomId: $e2eRoomID")
 
                 // Bob should be able to decrypt the message
-                testHelper.retryPeriodically {
+                testHelper.retryWithBackoff(
-                        val timelineEvent = bobSession.roomService().getRoom(e2eRoomID)?.timelineService()?.getTimelineEvent(aliceMessageId!!)
+                        onFail = {
+                            fail("Bob should be able to decrypt $aliceMessageId")
+                        }
+                ) {
+                    val timelineEvent = bobSession.roomService().getRoom(e2eRoomID)?.timelineService()?.getTimelineEvent(aliceMessageId!!)?.also {
+                        Log.v("#E2E TEST", "Bob sees ${it.root.getClearType()}")
+                    }
                     (timelineEvent != null &&
                             timelineEvent.isEncrypted() &&
                             timelineEvent.root.getClearType() == EventType.MESSAGE &&
@@ -135,7 +141,11 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
                     null
                     -> {
                         // Aris should be able to decrypt the message
-                        testHelper.retryPeriodically {
+                        testHelper.retryWithBackoff(
+                                onFail = {
+                                    fail("Aris should be able to decrypt $aliceMessageId")
+                                }
+                        ) {
                             val timelineEvent = arisSession.roomService().getRoom(e2eRoomID)?.timelineService()?.getTimelineEvent(aliceMessageId!!)
                             (timelineEvent != null &&
                                     timelineEvent.isEncrypted() &&
@@ -151,7 +161,11 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
                     RoomHistoryVisibility.INVITED,
                     RoomHistoryVisibility.JOINED -> {
                         // Aris should not even be able to get the message
-                        testHelper.retryPeriodically {
+                        testHelper.retryWithBackoff(
+                                onFail = {
+                                    fail("Aris should not even be able to get the message")
+                                }
+                        ) {
                             val timelineEvent = arisSession.roomService().getRoom(e2eRoomID)
                                     ?.timelineService()
                                     ?.getTimelineEvent(aliceMessageId!!)
@@ -258,11 +272,17 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
 
         // Bob should be able to decrypt the message
         var firstAliceMessageMegolmSessionId: String? = null
-        val bobRoomPov = bobSession.roomService().getRoom(e2eRoomID)
+        val bobRoomPov = bobSession.roomService().getRoom(e2eRoomID)!!
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff(
+                onFail = {
+                    fail("Bob should be able to decrypt $aliceMessageId")
+                }
+        ) {
             val timelineEvent = bobRoomPov
-                    ?.timelineService()
+                    .timelineService()
-                    ?.getTimelineEvent(aliceMessageId!!)
+                    .getTimelineEvent(aliceMessageId!!)?.also {
+                        Log.v("#E2E TEST ROTATION", "Bob sees ${it.root.getClearType()}")
+                    }
             (timelineEvent != null &&
                     timelineEvent.isEncrypted() &&
                     timelineEvent.root.getClearType() == EventType.MESSAGE).also {
@@ -279,11 +299,17 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
         Assert.assertNotNull("megolm session id can't be null", firstAliceMessageMegolmSessionId)
 
         var secondAliceMessageSessionId: String? = null
-        sendMessageInRoom(aliceRoomPOV, "Other msg", testHelper)?.let { secondMessage ->
+        sendMessageInRoom(aliceRoomPOV, "Other msg", testHelper)!!.let { secondMessage ->
-            testHelper.retryPeriodically {
+            testHelper.retryWithBackoff(
+                    onFail = {
+                        fail("Bob should be able to decrypt the second message $secondMessage")
+                    }
+            ) {
                 val timelineEvent = bobRoomPov
-                        ?.timelineService()
+                        .timelineService()
-                        ?.getTimelineEvent(secondMessage)
+                        .getTimelineEvent(secondMessage)?.also {
+                            Log.v("#E2E TEST ROTATION", "Bob sees ${it.root.getClearType()}")
+                        }
                 (timelineEvent != null &&
                         timelineEvent.isEncrypted() &&
                         timelineEvent.root.getClearType() == EventType.MESSAGE).also {
@@ -309,29 +335,44 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
                                 historyVisibilityStr = nextRoomHistoryVisibility.historyVisibilityStr
                         ).toContent()
                 )
+        Log.v("#E2E TEST ROTATION", "State update sent")
 
         // ensure that the state did synced down
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff(
-            aliceRoomPOV.stateService().getStateEvent(EventType.STATE_ROOM_HISTORY_VISIBILITY, QueryStringValue.IsEmpty)?.content
+                onFail = {
+                    fail("Alice state should be updated to ${nextRoomHistoryVisibility.historyVisibilityStr}")
+                }
+        ) {
+            aliceRoomPOV.stateService().getStateEvent(EventType.STATE_ROOM_HISTORY_VISIBILITY, QueryStringValue.IsEmpty)
+                    ?.content
+                    ?.also {
+                        Log.v("#E2E TEST ROTATION", "Alice sees state as $it")
+                    }
                     ?.toModel<RoomHistoryVisibilityContent>()?.historyVisibility == nextRoomHistoryVisibility.historyVisibility
         }
 
-        testHelper.retryPeriodically {
+//        testHelper.retryPeriodically {
-            val roomVisibility = aliceSession.getRoom(e2eRoomID)!!
+//            val roomVisibility = aliceSession.getRoom(e2eRoomID)!!
-                    .stateService()
+//                    .stateService()
-                    .getStateEvent(EventType.STATE_ROOM_HISTORY_VISIBILITY, QueryStringValue.IsEmpty)
+//                    .getStateEvent(EventType.STATE_ROOM_HISTORY_VISIBILITY, QueryStringValue.IsEmpty)
-                    ?.content
+//                    ?.content
-                    ?.toModel<RoomHistoryVisibilityContent>()
+//                    ?.toModel<RoomHistoryVisibilityContent>()
-            Log.v("#E2E TEST ROTATION", "Room visibility changed from: ${initRoomHistoryVisibility.name} to: ${roomVisibility?.historyVisibility?.name}")
+//            Log.v("#E2E TEST ROTATION", "Room visibility changed from: ${initRoomHistoryVisibility.name} to: ${roomVisibility?.historyVisibility?.name}")
-            roomVisibility?.historyVisibility == nextRoomHistoryVisibility.historyVisibility
+//            roomVisibility?.historyVisibility == nextRoomHistoryVisibility.historyVisibility
-        }
+//        }
 
         var aliceThirdMessageSessionId: String? = null
-        sendMessageInRoom(aliceRoomPOV, "Message after visibility change", testHelper)?.let { thirdMessage ->
+        sendMessageInRoom(aliceRoomPOV, "Message after visibility change", testHelper)!!.let { thirdMessage ->
-            testHelper.retryPeriodically {
+            testHelper.retryWithBackoff(
+                    onFail = {
+                        fail("Bob should be able to decrypt $thirdMessage")
+                    }
+            ) {
                 val timelineEvent = bobRoomPov
-                        ?.timelineService()
+                        .timelineService()
-                        ?.getTimelineEvent(thirdMessage)
+                        .getTimelineEvent(thirdMessage)?.also {
+                            Log.v("#E2E TEST ROTATION", "Bob sees ${it.root.getClearType()}")
+                        }
                 (timelineEvent != null &&
                         timelineEvent.isEncrypted() &&
                         timelineEvent.root.getClearType() == EventType.MESSAGE).also {
@@ -364,7 +405,7 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
     }
 
     private suspend fun ensureMembersHaveJoined(aliceSession: Session, otherAccounts: List<Session>, e2eRoomID: String, testHelper: CommonTestHelper) {
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff {
             otherAccounts.map {
                 aliceSession.roomService().getRoomMember(it.myUserId, e2eRoomID)?.membership
             }.all {
@@ -374,7 +415,7 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
     }
 
     private suspend fun waitForAndAcceptInviteInRoom(otherSession: Session, e2eRoomID: String, testHelper: CommonTestHelper) {
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff {
             val roomSummary = otherSession.roomService().getRoomSummary(e2eRoomID)
             (roomSummary != null && roomSummary.membership == Membership.INVITE).also {
                 if (it) {
@@ -383,17 +424,15 @@ class E2eeShareKeysHistoryTest : InstrumentedTest {
             }
         }
 
-        wrapWithTimeout(60_000) {
             Log.v("#E2E TEST", "${otherSession.myUserId} tries to join room $e2eRoomID")
             try {
                 otherSession.roomService().joinRoom(e2eRoomID)
             } catch (ex: JoinRoomFailure.JoinedWithTimeout) {
                 // it's ok we will wait after
             }
-        }
 
         Log.v("#E2E TEST", "${otherSession.myUserId} waiting for join echo ...")
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff {
             val roomSummary = otherSession.roomService().getRoomSummary(e2eRoomID)
             roomSummary != null && roomSummary.membership == Membership.JOIN
         }

matrix-sdk-android/src/androidTest/java/org/matrix/android/sdk/internal/crypto/verification/SasVerificationTestHelper.kt

@@ -16,6 +16,7 @@
 
 package org.matrix.android.sdk.internal.crypto.verification
 
+import org.amshove.kluent.fail
 import org.matrix.android.sdk.api.session.Session
 import org.matrix.android.sdk.api.session.crypto.verification.EVerificationState
 import org.matrix.android.sdk.api.session.crypto.verification.VerificationMethod
@@ -37,7 +38,11 @@ class SasVerificationTestHelper(private val testHelper: CommonTestHelper) {
         )
                 .transactionId
 
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff(
+                onFail = {
+                    fail("bob should see an incoming verification request with id $transactionId")
+                }
+        ) {
             val incomingRequest = bobVerificationService.getExistingVerificationRequest(aliceSession.myUserId, transactionId)
             if (incomingRequest != null) {
                 bobVerificationService.readyPendingVerification(
@@ -52,7 +57,11 @@ class SasVerificationTestHelper(private val testHelper: CommonTestHelper) {
         }
 
         // wait for alice to see the ready
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff(
+                onFail = {
+                    fail("Alice request whould be ready $transactionId")
+                }
+        ) {
             val pendingRequest = aliceVerificationService.getExistingVerificationRequest(bobUserId, transactionId)
             pendingRequest?.state == EVerificationState.Ready
         }
@@ -67,7 +76,7 @@ class SasVerificationTestHelper(private val testHelper: CommonTestHelper) {
         val requestID = session1VerificationService.requestSelfKeyVerification(supportedMethods).transactionId
 
         val myUserId = session1.myUserId
-        testHelper.retryPeriodically {
+        testHelper.retryWithBackoff {
             val incomingRequest = session2VerificationService.getExistingVerificationRequest(myUserId, requestID)
             if (incomingRequest != null) {
                 session2VerificationService.readyPendingVerification(

matrix-sdk-android/src/androidTestKotlinCrypto/java/org/matrix/android/sdk/internal/crypto/verification/SASTest.kt

@@ -17,100 +17,118 @@
 package org.matrix.android.sdk.internal.crypto.verification
 
 import androidx.test.ext.junit.runners.AndroidJUnit4
+import kotlinx.coroutines.CompletableDeferred
+import kotlinx.coroutines.CoroutineScope
+import kotlinx.coroutines.SupervisorJob
+import kotlinx.coroutines.flow.launchIn
+import kotlinx.coroutines.flow.onEach
+import org.amshove.kluent.internal.assertEquals
+import org.junit.Assert.assertNotNull
+import org.junit.Assert.assertNull
+import org.junit.Assert.assertTrue
 import org.junit.FixMethodOrder
-import org.junit.Ignore
+import org.junit.Test
 import org.junit.runner.RunWith
 import org.junit.runners.MethodSorters
 import org.matrix.android.sdk.InstrumentedTest
+import org.matrix.android.sdk.api.session.crypto.verification.CancelCode
+import org.matrix.android.sdk.api.session.crypto.verification.EVerificationState
+import org.matrix.android.sdk.api.session.crypto.verification.SasTransactionState
+import org.matrix.android.sdk.api.session.crypto.verification.SasVerificationTransaction
+import org.matrix.android.sdk.api.session.crypto.verification.VerificationEvent
+import org.matrix.android.sdk.api.session.crypto.verification.VerificationMethod
+import org.matrix.android.sdk.common.CommonTestHelper.Companion.runCryptoTest
+import timber.log.Timber
 
 @RunWith(AndroidJUnit4::class)
 @FixMethodOrder(MethodSorters.NAME_ASCENDING)
-@Ignore
 class SASTest : InstrumentedTest {
 
-    /*
+    val scope = CoroutineScope(SupervisorJob())
 
     @Test
     fun test_aliceStartThenAliceCancel() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
-        // TODO
+
-//        val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
+        Timber.v("verification: doE2ETestWithAliceAndBobInARoom")
-//        cryptoTestData.initializeCrossSigning(cryptoTestHelper)
+        val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
-//        val aliceSession = cryptoTestData.firstSession
+        Timber.v("verification: initializeCrossSigning")
-//        val bobSession = cryptoTestData.secondSession
+        cryptoTestData.initializeCrossSigning(cryptoTestHelper)
-//
+        val aliceSession = cryptoTestData.firstSession
-//        val aliceVerificationService = aliceSession.cryptoService().verificationService()
+        val bobSession = cryptoTestData.secondSession
-//        val bobVerificationService = bobSession!!.cryptoService().verificationService()
+
-//
+        val aliceVerificationService = aliceSession.cryptoService().verificationService()
-//        val bobTxCreatedLatch = CountDownLatch(1)
+        val bobVerificationService = bobSession!!.cryptoService().verificationService()
-//        val bobListener = object : VerificationService.Listener {
+
-//            override fun transactionUpdated(tx: VerificationTransaction) {
+        Timber.v("verification: requestVerificationAndWaitForReadyState")
-//                bobTxCreatedLatch.countDown()
+        val txId = SasVerificationTestHelper(testHelper)
-//            }
+                .requestVerificationAndWaitForReadyState(cryptoTestData, listOf(VerificationMethod.SAS))
-//        }
+
-//        bobVerificationService.addListener(bobListener)
+        Timber.v("verification: startKeyVerification")
-//
+        aliceVerificationService.startKeyVerification(
-//        val bobDevice = bobSession.cryptoService().getMyCryptoDevice()
+                VerificationMethod.SAS,
-//
+                bobSession.myUserId,
-//        aliceSession.cryptoService().downloadKeysIfNeeded(listOf(bobSession.myUserId), forceDownload = true)
+                txId
-//        val txID = aliceVerificationService.beginKeyVerification(bobSession.myUserId, bobDevice.deviceId)
+        )
-//
+
-//        assertNotNull("Alice should have a started transaction", txID)
+        Timber.v("verification: ensure bob has received starete")
-//
+        testHelper.retryWithBackoff {
-//        val aliceKeyTx = aliceVerificationService.getExistingTransaction(bobSession.myUserId, txID!!)
+            bobVerificationService.getExistingVerificationRequest(aliceSession.myUserId, txId)?.state == EVerificationState.Started
-//        assertNotNull("Alice should have a started transaction", aliceKeyTx)
-//
-//        testHelper.await(bobTxCreatedLatch)
-//        bobVerificationService.removeListener(bobListener)
-//
-//        val bobKeyTx = bobVerificationService.getExistingTransaction(aliceSession.myUserId, txID)
-//
-//        assertNotNull("Bob should have started verif transaction", bobKeyTx)
-//        assertTrue(bobKeyTx is SasVerificationTransaction)
-//        assertNotNull("Bob should have starting a SAS transaction", bobKeyTx)
-//        assertTrue(aliceKeyTx is SasVerificationTransaction)
-//        assertEquals("Alice and Bob have same transaction id", aliceKeyTx!!.transactionId, bobKeyTx!!.transactionId)
-//
-//        assertEquals("Alice state should be started", VerificationTxState.OnStarted, aliceKeyTx.state)
-//        assertEquals("Bob state should be started by alice", VerificationTxState.OnStarted, bobKeyTx.state)
-//
-//        // Let's cancel from alice side
-//        val cancelLatch = CountDownLatch(1)
-//
-//        val bobListener2 = object : VerificationService.Listener {
-//            override fun transactionUpdated(tx: VerificationTransaction) {
-//                if (tx.transactionId == txID) {
-//                    val immutableState = (tx as SasVerificationTransaction).state
-//                    if (immutableState is VerificationTxState.Cancelled && !immutableState.byMe) {
-//                        cancelLatch.countDown()
-//                    }
-//                }
-//            }
-//        }
-//        bobVerificationService.addListener(bobListener2)
-//
-//        aliceKeyTx.cancel(CancelCode.User)
-//
-//        testHelper.await(cancelLatch)
-//
-//        assertTrue("Should be cancelled on alice side", aliceKeyTx.state is VerificationTxState.Cancelled)
-//        assertTrue("Should be cancelled on bob side", bobKeyTx.state is VerificationTxState.Cancelled)
-//
-//        val aliceCancelState = aliceKeyTx.state as VerificationTxState.Cancelled
-//        val bobCancelState = bobKeyTx.state as VerificationTxState.Cancelled
-//
-//        assertTrue("Should be cancelled by me on alice side", aliceCancelState.byMe)
-//        assertFalse("Should be cancelled by other on bob side", bobCancelState.byMe)
-//
-//        assertEquals("Should be User cancelled on alice side", CancelCode.User, aliceCancelState.cancelCode)
-//        assertEquals("Should be User cancelled on bob side", CancelCode.User, bobCancelState.cancelCode)
-//
-//        assertNull(bobVerificationService.getExistingTransaction(aliceSession.myUserId, txID))
-//        assertNull(aliceVerificationService.getExistingTransaction(bobSession.myUserId, txID))
         }
 
-    @Test
+        val bobKeyTx = bobVerificationService.getExistingTransaction(aliceSession.myUserId, txId)
-    @Ignore("This test will be ignored until it is fixed")
+
-    fun test_key_agreement_protocols_must_include_curve25519() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+        assertNotNull("Bob should have started verif transaction", bobKeyTx)
+        assertTrue(bobKeyTx is SasVerificationTransaction)
+
+        val aliceKeyTx = aliceVerificationService.getExistingTransaction(bobSession.myUserId, txId)
+        assertTrue(aliceKeyTx is SasVerificationTransaction)
+
+        assertEquals("Alice and Bob have same transaction id", aliceKeyTx!!.transactionId, bobKeyTx!!.transactionId)
+
+        val aliceCancelled = CompletableDeferred<Unit>()
+        aliceVerificationService.requestEventFlow().onEach {
+            println("alice flow event $it")
+            if (it is VerificationEvent.TransactionUpdated && it.transactionId == txId) {
+                val sasVerificationTransaction = it.transaction as SasVerificationTransaction
+                if (sasVerificationTransaction.state() is SasTransactionState.Cancelled) {
+                    aliceCancelled.complete(Unit)
+                }
+            }
+        }.launchIn(scope)
+
+        val bobCancelled = CompletableDeferred<Unit>()
+        bobVerificationService.requestEventFlow().onEach {
+            println("alice flow event $it")
+            if (it is VerificationEvent.TransactionUpdated && it.transactionId == txId) {
+                val sasVerificationTransaction = it.transaction as SasVerificationTransaction
+                if (sasVerificationTransaction.state() is SasTransactionState.Cancelled) {
+                    bobCancelled.complete(Unit)
+                }
+            }
+        }.launchIn(scope)
+
+        aliceVerificationService.cancelVerificationRequest(bobSession.myUserId, txId)
+
+        aliceCancelled.await()
+        bobCancelled.await()
+
+        val cancelledAlice = aliceVerificationService.getExistingVerificationRequest(bobSession.myUserId, txId)!!
+        val cancelledBob = aliceVerificationService.getExistingVerificationRequest(aliceSession.myUserId, txId)!!
+
+        assertEquals("Should be cancelled on alice side", cancelledAlice.state, EVerificationState.Cancelled)
+        assertEquals("Should be cancelled on alice side", cancelledBob.state, EVerificationState.Cancelled)
+
+        assertEquals("Should be User cancelled on alice side", CancelCode.User, cancelledAlice.cancelConclusion)
+        assertEquals("Should be User cancelled on bob side", CancelCode.User, cancelledBob.cancelConclusion)
+
+        assertNull(bobVerificationService.getExistingTransaction(aliceSession.myUserId, txId))
+        assertNull(aliceVerificationService.getExistingTransaction(bobSession.myUserId, txId))
+    }
+
+    /*
+@Test
+@Ignore("This test will be ignored until it is fixed")
+fun test_key_agreement_protocols_must_include_curve25519() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     fail("Not passing for the moment")
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
 
@@ -166,11 +184,11 @@ class SASTest : InstrumentedTest {
     testHelper.await(cancelLatch)
 
     assertEquals("Request should be cancelled with m.unknown_method", CancelCode.UnknownMethod, cancelReason)
-    }
+}
 
-    @Test
+@Test
-    @Ignore("This test will be ignored until it is fixed")
+@Ignore("This test will be ignored until it is fixed")
-    fun test_key_agreement_macs_Must_include_hmac_sha256() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+fun test_key_agreement_macs_Must_include_hmac_sha256() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     fail("Not passing for the moment")
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
 
@@ -202,11 +220,11 @@ class SASTest : InstrumentedTest {
     testHelper.await(cancelLatch)
     val cancelReq = canceledToDeviceEvent!!.content.toModel<KeyVerificationCancel>()!!
     assertEquals("Request should be cancelled with m.unknown_method", CancelCode.UnknownMethod.value, cancelReq.code)
-    }
+}
 
-    @Test
+@Test
-    @Ignore("This test will be ignored until it is fixed")
+@Ignore("This test will be ignored until it is fixed")
-    fun test_key_agreement_short_code_include_decimal() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+fun test_key_agreement_short_code_include_decimal() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     fail("Not passing for the moment")
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
 
@@ -239,9 +257,9 @@ class SASTest : InstrumentedTest {
 
     val cancelReq = canceledToDeviceEvent!!.content.toModel<KeyVerificationCancel>()!!
     assertEquals("Request should be cancelled with m.unknown_method", CancelCode.UnknownMethod.value, cancelReq.code)
-    }
+}
 
-    private suspend fun fakeBobStart(
+private suspend fun fakeBobStart(
         bobSession: Session,
         aliceUserID: String?,
         aliceDevice: String?,
@@ -250,7 +268,7 @@ class SASTest : InstrumentedTest {
         hashes: List<String> = SasVerificationTransaction.KNOWN_HASHES,
         mac: List<String> = SasVerificationTransaction.KNOWN_MACS,
         codes: List<String> = SasVerificationTransaction.KNOWN_SHORT_CODES
-    ) {
+) {
     val startMessage = KeyVerificationStart(
             fromDevice = bobSession.cryptoService().getMyCryptoDevice().deviceId,
             method = VerificationMethod.SAS.toValue(),
@@ -271,12 +289,12 @@ class SASTest : InstrumentedTest {
     // TODO         tid,
     // TODO         TestMatrixCallback<Void>(sendLatch)
     // TODO )
-    }
+}
 
-    // any two devices may only have at most one key verification in flight at a time.
+// any two devices may only have at most one key verification in flight at a time.
-    // If a device has two verifications in progress with the same device, then it should cancel both verifications.
+// If a device has two verifications in progress with the same device, then it should cancel both verifications.
-    @Test
+@Test
-    fun test_aliceStartTwoRequests() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+fun test_aliceStartTwoRequests() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
 
     val aliceSession = cryptoTestData.firstSession
@@ -313,9 +331,9 @@ class SASTest : InstrumentedTest {
 //        testHelper.await(aliceCancelledLatch)
 
     cryptoTestData.cleanUp(testHelper)
-    }
+}
 
-    /**
+/**
      * Test that when alice starts a 'correct' request, bob agrees.
      */
 //    @Test
@@ -416,8 +434,8 @@ class SASTest : InstrumentedTest {
 //        )
 //    }
 
-    @Test
+@Test
-    fun test_happyPath() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+fun test_happyPath() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
     cryptoTestData.initializeCrossSigning(cryptoTestHelper)
     val sasVerificationTestHelper = SasVerificationTestHelper(testHelper, cryptoTestHelper)
@@ -520,10 +538,10 @@ class SASTest : InstrumentedTest {
 
     assertTrue("alice device should be verified from bob point of view", aliceDeviceInfoFromBobPOV!!.isVerified)
     assertTrue("bob device should be verified from alice point of view", bobDeviceInfoFromAlicePOV!!.isVerified)
-    }
+}
 
-    @Test
+@Test
-    fun test_ConcurrentStart() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
+fun test_ConcurrentStart() = runCryptoTest(context()) { cryptoTestHelper, testHelper ->
     val cryptoTestData = cryptoTestHelper.doE2ETestWithAliceAndBobInARoom()
     cryptoTestData.initializeCrossSigning(cryptoTestHelper)
     val aliceSession = cryptoTestData.firstSession
@@ -589,7 +607,7 @@ class SASTest : InstrumentedTest {
         Log.v("TEST", "== bobPovTx is $bobPovTx")
         bobPovTx?.state() == SasTransactionState.SasShortCodeReady
     }
-    }
+}
 
      */
 }

matrix-sdk-android/src/kotlinCrypto/java/org/matrix/android/sdk/internal/crypto/verification/VerificationActor.kt

@@ -263,6 +263,8 @@ internal class VerificationActor @AssistedInject constructor(
             }
             is VerificationIntent.GetExistingRequestsForUser -> {
                 verificationRequestsStore.getExistingRequestsForUser(msg.userId).let { requests ->
+                    Timber.tag(loggerTag.value)
+                            .v("[${myUserId.take(8)}]: Found $requests")
                     msg.deferred.complete(requests.map { it.toPendingVerificationRequest() })
                 }
             }
@@ -306,6 +308,8 @@ internal class VerificationActor @AssistedInject constructor(
     private fun dispatchUpdate(update: VerificationEvent) {
         // We don't want to block on emit.
         // If no subscriber there is a small buffer
+        Timber.tag(loggerTag.value)
+                .v("[${myUserId.take(8)}] Dispatch Request update ${update.transactionId}")
         scope.launch {
             eventFlow.emit(update)
         }
@@ -565,21 +569,29 @@ internal class VerificationActor @AssistedInject constructor(
     private suspend fun handleSasStart(msg: VerificationIntent.ActionStartSasVerification) {
         val matchingRequest = verificationRequestsStore.getExistingRequestWithRequestId(msg.requestId)
                 ?: return Unit.also {
+                    Timber.tag(loggerTag.value)
+                            .v("[${myUserId.take(8)}]: Can't start unknown request ${msg.requestId}")
                     msg.deferred.completeExceptionally(java.lang.IllegalArgumentException("Unknown request"))
                 }
 
         if (matchingRequest.state != EVerificationState.Ready) {
+            Timber.tag(loggerTag.value)
+                    .v("[${myUserId.take(8)}]: Can't start a non ready request ${msg.requestId}")
             msg.deferred.completeExceptionally(java.lang.IllegalStateException("Can't start a non ready request"))
             return
         }
 
         val otherDeviceId = matchingRequest.otherDeviceId() ?: return Unit.also {
+            Timber.tag(loggerTag.value)
+                    .v("[${myUserId.take(8)}]: Can't start null other device id ${msg.requestId}")
             msg.deferred.completeExceptionally(java.lang.IllegalArgumentException("Failed to find other device Id"))
         }
 
         val existingTransaction = getExistingTransaction<VerificationTransaction>(msg.otherUserId, msg.requestId)
         if (existingTransaction is SasVerificationTransaction) {
             // there is already an existing transaction??
+            Timber.tag(loggerTag.value)
+                    .v("[${myUserId.take(8)}]: Can't start, already started ${msg.requestId}")
             msg.deferred.completeExceptionally(IllegalStateException("Already started"))
             return
         }
@@ -589,12 +601,17 @@ internal class VerificationActor @AssistedInject constructor(
                 requestId = msg.requestId
         )
 
+        Timber.tag(loggerTag.value)
+                .v("[${myUserId.take(8)}]:sending start to other ${msg.requestId} in room ${matchingRequest.roomId}")
         transportLayer.sendToOther(
                 matchingRequest,
                 EventType.KEY_VERIFICATION_START,
                 startMessage,
         )
 
+        Timber.tag(loggerTag.value)
+                .v("[${myUserId.take(8)}]: start sent to other ${msg.requestId}")
+
         // should check if already one (and cancel it)
         val tx = KotlinSasTransaction(
                 channel = channel,
@@ -1262,6 +1279,9 @@ internal class VerificationActor @AssistedInject constructor(
             null
         }
 
+        Timber.tag(loggerTag.value)
+                .v("[${myUserId.take(8)}] Request ${msg.transactionId} code is $qrCodeData")
+
         val readyInfo = ValidVerificationInfoReady(
                 msg.transactionId,
                 verificationTrustBackend.getMyDeviceId(),
@@ -1274,9 +1294,14 @@ internal class VerificationActor @AssistedInject constructor(
                 methods = commonMethods,
                 fromDevice = verificationTrustBackend.getMyDeviceId()
         )
+
+        Timber.tag(loggerTag.value)
+                .v("[${myUserId.take(8)}] Request ${msg.transactionId} sending ready")
         try {
             transportLayer.sendToOther(existing, EventType.KEY_VERIFICATION_READY, message)
         } catch (failure: Throwable) {
+            Timber.tag(loggerTag.value)
+                    .v("[${myUserId.take(8)}] Request ${msg.transactionId} failed to send ready")
             msg.deferred.completeExceptionally(failure)
             return
         }

matrix-sdk-android/src/kotlinCrypto/java/org/matrix/android/sdk/internal/crypto/verification/VerificationMessageProcessor.kt

@@ -18,9 +18,9 @@ package org.matrix.android.sdk.internal.crypto.verification
 import org.matrix.android.sdk.api.session.crypto.verification.VerificationService
 import org.matrix.android.sdk.api.session.events.model.Event
 import org.matrix.android.sdk.api.session.events.model.EventType
+import org.matrix.android.sdk.api.session.events.model.getRelationContent
 import org.matrix.android.sdk.api.session.events.model.toModel
 import org.matrix.android.sdk.api.session.room.model.message.MessageContent
-import org.matrix.android.sdk.api.session.room.model.message.MessageRelationContent
 import org.matrix.android.sdk.api.session.room.model.message.MessageType
 import org.matrix.android.sdk.api.session.room.model.message.MessageVerificationReadyContent
 import org.matrix.android.sdk.internal.di.DeviceId
@@ -55,19 +55,19 @@ internal class VerificationMessageProcessor @Inject constructor(
     }
 
     suspend fun process(roomId: String, event: Event) {
-        Timber.v("## SAS Verification live observer: received msgId: ${event.eventId} msgtype: ${event.getClearType()} from ${event.senderId}")
+        Timber.v("## SAS Verification[${userId.take(5)}] live observer: received msgId: ${event.eventId} msgtype: ${event.getClearType()} from ${event.senderId}")
 
         // If the request is in the future by more than 5 minutes or more than 10 minutes in the past,
         // the message should be ignored by the receiver.
 
         if (!VerificationService.isValidRequest(event.ageLocalTs, clock.epochMillis())) return Unit.also {
-            Timber.d("## SAS Verification live observer: msgId: ${event.eventId} is outdated age:${event.ageLocalTs} ms")
+            Timber.d("## SAS Verification[${userId.take(5)}] live observer: msgId: ${event.eventId} is outdated age:${event.ageLocalTs} ms")
         }
 
-        Timber.v("## SAS Verification live observer: received msgId: ${event.eventId} type: ${event.getClearType()}")
+        Timber.v("## SAS Verification[${userId.take(5)}] live observer: received msgId: ${event.eventId} type: ${event.getClearType()}")
 
         // Relates to is not encrypted
-        val relatesToEventId = event.content.toModel<MessageRelationContent>()?.relatesTo?.eventId
+        val relatesToEventId = event.getRelationContent()?.eventId
 
         if (event.senderId == userId) {
             // If it's send from me, we need to keep track of Requests or Start
@@ -78,7 +78,7 @@ internal class VerificationMessageProcessor @Inject constructor(
 //                    event.getClearContent().toModel<MessageVerificationRequestContent>()?.let {
 //                        if (it.fromDevice != deviceId) {
 //                            // The verification is requested from another device
-//                            Timber.v("## SAS Verification live observer: Transaction requested from other device  tid:${event.eventId} ")
+//                            Timber.v("## SAS Verification[$userItakeng5 live observer: Transaction requested from other device  tid:${event.eventId} ")
 //                            event.eventId?.let { txId -> transactionsHandledByOtherDevice.add(txId) }
 //                        }
 //                    }
@@ -87,7 +87,7 @@ internal class VerificationMessageProcessor @Inject constructor(
 //                event.getClearContent().toModel<MessageVerificationStartContent>()?.let {
 //                    if (it.fromDevice != deviceId) {
 //                        // The verification is started from another device
-//                        Timber.v("## SAS Verification live observer: Transaction started by other device  tid:$relatesToEventId ")
+//                        Timber.v("## SAS Verification[$userItakeng5 live observer: Transaction started by other device  tid:$relatesToEventId ")
 //                        relatesToEventId?.let { txId -> transactionsHandledByOtherDevice.add(txId) }
 //                        verificationService.onRoomRequestHandledByOtherDevice(event)
 //                    }
@@ -98,14 +98,15 @@ internal class VerificationMessageProcessor @Inject constructor(
                     event.getClearContent().toModel<MessageVerificationReadyContent>()?.let {
                         if (it.fromDevice != deviceId) {
                             // The verification is started from another device
-                            Timber.v("## SAS Verification live observer: Transaction started by other device  tid:$relatesToEventId ")
+                            Timber.v("## SAS Verification[${userId.take(5)}] live observer: Transaction started by other device  tid:$relatesToEventId ")
                             relatesToEventId?.let { txId -> transactionsHandledByOtherDevice.add(txId) }
                             verificationService.onRoomReadyFromOneOfMyOtherDevice(event)
                         }
                     }
-                } else {
-                    Timber.v("## SAS Verification ignoring message sent by me: ${event.eventId} type: ${event.getClearType()}")
                 }
+//                else {
+//                    Timber.v("## SAS Verification[${userId.take(5)}] ignoring message sent by me: ${event.eventId} type: ${event.getClearType()}")
+//                }
 //            } else if (EventType.KEY_VERIFICATION_CANCEL == event.getClearType() || EventType.KEY_VERIFICATION_DONE == event.getClearType()) {
 //                relatesToEventId?.let {
 //                    transactionsHandledByOtherDevice.remove(it)
@@ -114,13 +115,13 @@ internal class VerificationMessageProcessor @Inject constructor(
 //            } else if (EventType.ENCRYPTED == event.getClearType()) {
 //                verificationService.onPotentiallyInterestingEventRoomFailToDecrypt(event)
 //            }
-
+            Timber.v("## SAS Verification[${userId.take(5)}] discard from me msgId: ${event.eventId}")
             return
         }
 
         if (relatesToEventId != null && transactionsHandledByOtherDevice.contains(relatesToEventId)) {
             // Ignore this event, it is directed to another of my devices
-            Timber.v("## SAS Verification live observer: Ignore Transaction handled by other device  tid:$relatesToEventId ")
+            Timber.v("## SAS Verification[${userId.take(5)}] live observer: Ignore Transaction handled by other device  tid:$relatesToEventId ")
             return
         }
         when (event.getClearType()) {

matrix-sdk-android/src/rustCrypto/java/org/matrix/android/sdk/internal/crypto/SecretShareManager.kt

@@ -16,11 +16,15 @@
 
 package org.matrix.android.sdk.internal.crypto
 
+import org.matrix.android.sdk.BuildConfig
+import timber.log.Timber
 import javax.inject.Inject
 
 internal class SecretShareManager @Inject constructor() {
 
     suspend fun requestSecretTo(deviceId: String, secretName: String) {
         // nop in rust?
+        if (BuildConfig.DEBUG) TODO("requestSecretTo Not implemented in Rust")
+        Timber.e("SecretShareManager Not supported in rust $deviceId, $secretName")
     }
 }

matrix-sdk-android/src/rustCrypto/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/UnRequestedForwardManager.kt

@@ -16,11 +16,13 @@
 
 package org.matrix.android.sdk.internal.crypto.algorithms.megolm
 
+import timber.log.Timber
 import javax.inject.Inject
 
 // empty in rust
 class UnRequestedForwardManager @Inject constructor() {
 
-    fun onInviteReceived(roomId: String, orEmpty: String, epochMillis: Long) {
+    fun onInviteReceived(roomId: String, inviterId: String, epochMillis: Long) {
+        Timber.e("UnRequestedForwardManager not yet implemented $roomId, $inviterId, $epochMillis")
     }
 }

matrix-sdk-android/src/rustCrypto/java/org/matrix/android/sdk/internal/crypto/network/RequestSender.kt

@@ -239,9 +239,9 @@ internal class RequestSender @Inject constructor(
                             val hashMap = content as? Map<*, *>
                             val action = hashMap?.get("action")?.toString()
                             if (GossipingToDeviceObject.ACTION_SHARE_REQUEST == action) {
-                                val body = hashMap.get("body") as? Map<*, *>
+                                val requestBody = hashMap["body"] as? Map<*, *>
-                                val roomId = body?.get("room_id") as? String
+                                val roomId = requestBody?.get("room_id") as? String
-                                val sessionId = body?.get("session_id") as? String
+                                val sessionId = requestBody?.get("session_id") as? String
                                 if (roomId != null && sessionId != null) {
                                     rateLimiter.tryFromBackupIfPossible(sessionId, roomId)
                                 }