fix(marmot): add diagnostic logs to group persistence path + use explicit AndroidKeyStore provider

User-reported issue: creating a Marmot group works in a single session, but the group is gone after app restart. The store code path survives the persistGroup save on creation, but something between save and restore silently loses the state. Changes: - KeyStoreEncryption: pass "AndroidKeyStore" explicitly to KeyGenerator.getInstance so generator.init(KeyGenParameterSpec) is guaranteed to land on the AndroidKeyStore provider (the default provider selection is not guaranteed to choose it). Also wrap encrypt/decrypt in try/catch so the real exception is logged instead of bubbling up as a generic failure. - AndroidMlsGroupStateStore: log rootDir at construction, and log every save/load/listGroups/delete with file paths, byte counts, and whether the target file actually exists after writing. Any thrown exception is now logged with full stack trace before rethrowing. - MlsGroupManager: log create / persist / restoreAll with group ids, byte counts, and in-memory group count so we can see exactly which step drops state. The existing "corrupted state, delete" branch now logs at ERROR with a clearer marker so it's easy to spot in the logs. - MarmotManager + AccountCacheState: log which MLS store implementation is chosen per account (Android vs InMemory fallback) and the root filesDir path, plus restoreAll() begin/end with restored group ids. These logs should make it obvious whether: 1. persistence is silently falling back to InMemoryMlsGroupStateStore, 2. save is actually writing the file to disk, 3. listGroups is finding the directory on restart, 4. decrypt is throwing and the restoreAll catch block is wiping the "corrupted" state. https://claude.ai/code/session_014EKS8JBwSpap34aM6FnYLm
2026-04-15 18:24:58 +00:00
parent 558eb984a0
commit 7f2d44df7e
5 changed files with 137 additions and 46 deletions
@@ -100,15 +100,22 @@ class AccountCacheState(

        val mlsStore =
            try {
-                AndroidMlsGroupStateStore(rootFilesDir())
+                val dir = rootFilesDir()
+                Log.d("AccountCacheState") {
+                    "Initializing AndroidMlsGroupStateStore for ${signer.pubKey.take(8)}… at ${dir.absolutePath}"
+                }
+                AndroidMlsGroupStateStore(dir)
            } catch (e: Exception) {
                Log.e(
                    "AccountCacheState",
-                    "Failed to initialize AndroidMlsGroupStateStore, falling back to in-memory store (Marmot groups will not persist across restarts)",
+                    "Failed to initialize AndroidMlsGroupStateStore, falling back to in-memory store (Marmot groups will NOT persist across restarts)",
                    e,
                )
                InMemoryMlsGroupStateStore()
            }
+        Log.d("AccountCacheState") {
+            "Account ${signer.pubKey.take(8)}… using Marmot store: ${mlsStore::class.simpleName}"
+        }

        return Account(
            settings = accountSettings,
@@ -43,6 +43,13 @@ class AndroidMlsGroupStateStore(
    private val rootDir: File,
    private val encryption: KeyStoreEncryption = KeyStoreEncryption(),
 ) : MlsGroupStateStore {
+    init {
+        Log.d(TAG) {
+            "Initialized AndroidMlsGroupStateStore: rootDir=${rootDir.absolutePath}, " +
+                "mls_groups exists=${File(rootDir, "mls_groups").exists()}"
+        }
+    }
+
    private fun groupDir(nostrGroupId: String): File {
        // Validate nostrGroupId is a hex string to prevent path traversal
        require(nostrGroupId.matches(HEX_PATTERN)) {
@@ -52,6 +59,7 @@ class AndroidMlsGroupStateStore(
    }

    companion object {
+        private const val TAG = "AndroidMlsGroupStateStore"
        private val HEX_PATTERN = Regex("^[0-9a-fA-F]+$")
    }

@@ -64,20 +72,44 @@ class AndroidMlsGroupStateStore(
        state: ByteArray,
    ) = withContext(Dispatchers.IO) {
        val file = stateFile(nostrGroupId)
-        file.parentFile?.mkdirs()
-        atomicWrite(file, encryption.encrypt(state))
+        Log.d(TAG) { "save($nostrGroupId): ${state.size} bytes → ${file.absolutePath}" }
+        try {
+            file.parentFile?.mkdirs()
+            val encrypted = encryption.encrypt(state)
+            atomicWrite(file, encrypted)
+            Log.d(TAG) {
+                "save($nostrGroupId): wrote ${encrypted.size} encrypted bytes, " +
+                    "file exists=${file.exists()}, file size=${if (file.exists()) file.length() else -1}"
+            }
+        } catch (e: Exception) {
+            Log.e(TAG, "save($nostrGroupId) FAILED: ${e.message}", e)
+            throw e
+        }
    }

    override suspend fun load(nostrGroupId: String): ByteArray? =
        withContext(Dispatchers.IO) {
            val file = stateFile(nostrGroupId)
-            if (!file.exists()) return@withContext null
-            encryption.decrypt(file.readBytes())
+            if (!file.exists()) {
+                Log.d(TAG) { "load($nostrGroupId): file does not exist at ${file.absolutePath}" }
+                return@withContext null
+            }
+            try {
+                val bytes = file.readBytes()
+                Log.d(TAG) { "load($nostrGroupId): read ${bytes.size} encrypted bytes from ${file.absolutePath}" }
+                val decrypted = encryption.decrypt(bytes)
+                Log.d(TAG) { "load($nostrGroupId): decrypted to ${decrypted?.size ?: -1} bytes" }
+                decrypted
+            } catch (e: Exception) {
+                Log.e(TAG, "load($nostrGroupId) FAILED: ${e.message}", e)
+                throw e
+            }
        }

    override suspend fun delete(nostrGroupId: String) {
        withContext(Dispatchers.IO) {
            val dir = groupDir(nostrGroupId)
+            Log.w(TAG) { "delete($nostrGroupId): deleting ${dir.absolutePath}" }
            dir.deleteRecursively()
        }
    }
@@ -85,12 +117,20 @@ class AndroidMlsGroupStateStore(
    override suspend fun listGroups(): List<String> =
        withContext(Dispatchers.IO) {
            val baseDir = File(rootDir, "mls_groups")
-            if (!baseDir.exists()) return@withContext emptyList()
-            baseDir
-                .listFiles()
-                ?.filter { it.isDirectory && File(it, "state").exists() }
-                ?.map { it.name }
-                ?: emptyList()
+            if (!baseDir.exists()) {
+                Log.d(TAG) { "listGroups(): base dir does not exist at ${baseDir.absolutePath}" }
+                return@withContext emptyList()
+            }
+            val allEntries = baseDir.listFiles()?.toList() ?: emptyList()
+            val result =
+                allEntries
+                    .filter { it.isDirectory && File(it, "state").exists() }
+                    .map { it.name }
+            Log.d(TAG) {
+                "listGroups(): ${baseDir.absolutePath} has ${allEntries.size} entries, " +
+                    "${result.size} valid groups: $result"
+            }
+            result
        }

    override suspend fun saveRetainedEpochs(
@@ -24,6 +24,7 @@ import android.os.Build
 import android.security.keystore.KeyGenParameterSpec
 import android.security.keystore.KeyProperties
 import android.security.keystore.StrongBoxUnavailableException
+import com.vitorpamplona.quartz.utils.Log
 import java.security.KeyStore
 import javax.crypto.Cipher
 import javax.crypto.KeyGenerator
@@ -32,6 +33,8 @@ import javax.crypto.spec.IvParameterSpec

 class KeyStoreEncryption {
    companion object {
+        private const val TAG = "KeyStoreEncryption"
+        private const val ANDROID_KEY_STORE = "AndroidKeyStore"
        private const val ALGORITHM = KeyProperties.KEY_ALGORITHM_AES
        private const val BLOCK_MODE = KeyProperties.BLOCK_MODE_GCM
        private const val PADDING = KeyProperties.ENCRYPTION_PADDING_PKCS7
@@ -42,7 +45,7 @@ class KeyStoreEncryption {
    }

    private val cipher = Cipher.getInstance(TRANSFORMATION)
-    private val keyStore = KeyStore.getInstance("AndroidKeyStore").apply { load(null) }
+    private val keyStore = KeyStore.getInstance(ANDROID_KEY_STORE).apply { load(null) }

    private fun getKey(): SecretKey {
        val existingKey = keyStore.getEntry(KEY_ALIAS, null) as? KeyStore.SecretKeyEntry
@@ -60,7 +63,7 @@ class KeyStoreEncryption {
                        .setIsStrongBoxBacked(true)
                        .build()

-                val generator = KeyGenerator.getInstance(ALGORITHM)
+                val generator = KeyGenerator.getInstance(ALGORITHM, ANDROID_KEY_STORE)
                generator.init(keyParams)
                generator.generateKey()
            } catch (_: StrongBoxUnavailableException) {
@@ -78,28 +81,41 @@ class KeyStoreEncryption {
                .setEncryptionPaddings(PADDING)
                .build()

-        val generator = KeyGenerator.getInstance(ALGORITHM)
+        val generator = KeyGenerator.getInstance(ALGORITHM, ANDROID_KEY_STORE)
        generator.init(keyParams)
        return generator.generateKey()
    }

-    private fun createKey(): SecretKey = createKeyStrongBoxIfAvailable() ?: createKeyRegular()
+    private fun createKey(): SecretKey {
+        Log.d(TAG) { "Creating new AES key in AndroidKeyStore (alias=$KEY_ALIAS)" }
+        return createKeyStrongBoxIfAvailable() ?: createKeyRegular()
+    }

    fun encrypt(bytes: ByteArray): ByteArray {
-        // Initializes the cipher in encrypt mode and encrypts data
-        cipher.init(Cipher.ENCRYPT_MODE, getKey())
-        val iv = cipher.iv
-        val encrypted = cipher.doFinal(bytes)
-        return iv + encrypted
+        try {
+            // Initializes the cipher in encrypt mode and encrypts data
+            cipher.init(Cipher.ENCRYPT_MODE, getKey())
+            val iv = cipher.iv
+            val encrypted = cipher.doFinal(bytes)
+            return iv + encrypted
+        } catch (e: Exception) {
+            Log.e(TAG, "encrypt() failed: ${e.message}", e)
+            throw e
+        }
    }

    fun decrypt(bytes: ByteArray): ByteArray? {
-        // Extracts IV and decrypts the data. GCM mode uses a 12-byte IV,
-        // which is what cipher.iv returns in encrypt() — not the AES block
-        // size (16), which is what cipher.blockSize would return.
-        val iv = bytes.copyOfRange(0, GCM_IV_LENGTH)
-        val data = bytes.copyOfRange(GCM_IV_LENGTH, bytes.size)
-        cipher.init(Cipher.DECRYPT_MODE, getKey(), IvParameterSpec(iv))
-        return cipher.doFinal(data)
+        try {
+            // Extracts IV and decrypts the data. GCM mode uses a 12-byte IV,
+            // which is what cipher.iv returns in encrypt() — not the AES block
+            // size (16), which is what cipher.blockSize would return.
+            val iv = bytes.copyOfRange(0, GCM_IV_LENGTH)
+            val data = bytes.copyOfRange(GCM_IV_LENGTH, bytes.size)
+            cipher.init(Cipher.DECRYPT_MODE, getKey(), IvParameterSpec(iv))
+            return cipher.doFinal(data)
+        } catch (e: Exception) {
+            Log.e(TAG, "decrypt() failed (input ${bytes.size} bytes): ${e.message}", e)
+            throw e
+        }
    }
 }
@@ -76,10 +76,12 @@ class MarmotManager(
     * Call once during Account initialization.
     */
    suspend fun restoreAll() {
+        Log.d("MarmotManager") { "restoreAll(): begin for ${signer.pubKey.take(8)}…" }
        try {
            groupManager.restoreAll()
-            subscriptionManager.syncWithGroupManager(groupManager.activeGroupIds())
-            Log.d("MarmotManager", "Restored ${groupManager.activeGroupIds().size} groups")
+            val activeIds = groupManager.activeGroupIds()
+            subscriptionManager.syncWithGroupManager(activeIds)
+            Log.d("MarmotManager") { "restoreAll(): done, ${activeIds.size} groups: $activeIds" }
        } catch (e: Exception) {
            Log.e("MarmotManager", "Failed to restore Marmot state", e)
        }
@@ -194,9 +196,11 @@ class MarmotManager(
     * Create a new MLS group.
     */
    suspend fun createGroup(nostrGroupId: HexKey): HexKey {
+        Log.d("MarmotManager") { "createGroup($nostrGroupId): by ${signer.pubKey.take(8)}…" }
        val identity = signer.pubKey.hexToByteArray()
        groupManager.createGroup(nostrGroupId, identity)
        subscriptionManager.subscribeGroup(nostrGroupId)
+        Log.d("MarmotManager") { "createGroup($nostrGroupId): persisted and subscribed" }
        return nostrGroupId
    }

@@ -105,11 +105,17 @@ class MlsGroupManager(
    suspend fun restoreAll() =
        mutex.withLock {
            val groupIds = store.listGroups()
+            Log.d(TAG) { "restoreAll(): store reports ${groupIds.size} groups: $groupIds" }
            for (nostrGroupId in groupIds) {
                try {
-                    val stateBytes = store.load(nostrGroupId) ?: continue
+                    val stateBytes = store.load(nostrGroupId)
+                    if (stateBytes == null) {
+                        Log.w(TAG) { "restoreAll(): load returned null for $nostrGroupId, skipping" }
+                        continue
+                    }
                    val state = MlsGroupState.decodeTls(stateBytes)
                    groups[nostrGroupId] = MlsGroup.restore(state)
+                    Log.d(TAG) { "restoreAll(): restored group $nostrGroupId (${stateBytes.size} bytes)" }

                    // Restore retained epochs
                    val retained = store.loadRetainedEpochs(nostrGroupId)
@@ -118,17 +124,19 @@ class MlsGroupManager(
                            retained
                                .map { RetainedEpochSecrets.decodeTls(TlsReader(it)) }
                                .toMutableList()
+                        Log.d(TAG) { "restoreAll(): restored ${retained.size} retained epochs for $nostrGroupId" }
                    }
                } catch (e: Exception) {
                    // Corrupted state — log and remove it so it doesn't block future joins
                    Log.e(
-                        "MlsGroupManager",
-                        "Corrupted state for group $nostrGroupId, deleting: ${e.message}",
+                        TAG,
+                        "restoreAll(): Corrupted state for group $nostrGroupId, DELETING: ${e.message}",
                        e,
                    )
                    store.delete(nostrGroupId)
                }
            }
+            Log.d(TAG) { "restoreAll(): finished with ${groups.size} active groups in memory" }
        }

    /**
@@ -162,9 +170,11 @@ class MlsGroupManager(
        signingKey: ByteArray? = null,
    ): MlsGroup =
        mutex.withLock {
+            Log.d(TAG) { "createGroup($nostrGroupId): creating new MLS group" }
            val group = MlsGroup.create(identity, signingKey)
            groups[nostrGroupId] = group
            persistGroup(nostrGroupId)
+            Log.d(TAG) { "createGroup($nostrGroupId): done, in-memory group count=${groups.size}" }
            group
        }

@@ -467,20 +477,32 @@ class MlsGroupManager(
            ?: throw IllegalStateException("Not a member of group $nostrGroupId")

    private suspend fun persistGroup(nostrGroupId: HexKey) {
-        val group = groups[nostrGroupId] ?: return
-        val state = group.saveState()
-        store.save(nostrGroupId, state.encodeTls())
+        val group = groups[nostrGroupId]
+        if (group == null) {
+            Log.w(TAG) { "persistGroup($nostrGroupId): group not in memory, skipping" }
+            return
+        }
+        try {
+            val state = group.saveState()
+            val encoded = state.encodeTls()
+            Log.d(TAG) { "persistGroup($nostrGroupId): serialized ${encoded.size} bytes, calling store.save" }
+            store.save(nostrGroupId, encoded)

-        // Also persist retained epochs
-        val retained = retainedEpochs[nostrGroupId]
-        if (retained != null) {
-            val retainedBytes =
-                retained.map { epoch ->
-                    val writer = TlsWriter()
-                    epoch.encodeTls(writer)
-                    writer.toByteArray()
-                }
-            store.saveRetainedEpochs(nostrGroupId, retainedBytes)
+            // Also persist retained epochs
+            val retained = retainedEpochs[nostrGroupId]
+            if (retained != null) {
+                val retainedBytes =
+                    retained.map { epoch ->
+                        val writer = TlsWriter()
+                        epoch.encodeTls(writer)
+                        writer.toByteArray()
+                    }
+                store.saveRetainedEpochs(nostrGroupId, retainedBytes)
+                Log.d(TAG) { "persistGroup($nostrGroupId): persisted ${retainedBytes.size} retained epochs" }
+            }
+        } catch (e: Exception) {
+            Log.e(TAG, "persistGroup($nostrGroupId) FAILED: ${e.message}", e)
+            throw e
        }
    }

@@ -581,6 +603,8 @@ class MlsGroupManager(
        }

    companion object {
+        private const val TAG = "MlsGroupManager"
+
        /**
         * Number of past epochs to retain for late-arriving message decryption.
         * MLS forward secrecy guarantees mean we want to limit this window.