From 7f2d44df7e4d6ffb8ce5223c80f620854e7a4138 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 15 Apr 2026 18:24:58 +0000 Subject: [PATCH] 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 --- .../model/accountsCache/AccountCacheState.kt | 11 +++- .../model/marmot/AndroidMlsGroupStateStore.kt | 60 +++++++++++++++---- .../model/preferences/KeyStoreEncryption.kt | 48 ++++++++++----- .../amethyst/commons/marmot/MarmotManager.kt | 8 ++- .../marmot/mls/group/MlsGroupManager.kt | 56 ++++++++++++----- 5 files changed, 137 insertions(+), 46 deletions(-) diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/accountsCache/AccountCacheState.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/accountsCache/AccountCacheState.kt index 50d5c1d3d..c4daa86e0 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/accountsCache/AccountCacheState.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/accountsCache/AccountCacheState.kt @@ -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, diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/marmot/AndroidMlsGroupStateStore.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/marmot/AndroidMlsGroupStateStore.kt index 1cdf110ae..f20268081 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/marmot/AndroidMlsGroupStateStore.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/marmot/AndroidMlsGroupStateStore.kt @@ -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 = 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( diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/preferences/KeyStoreEncryption.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/preferences/KeyStoreEncryption.kt index 2a0500560..ae0ad9f2c 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/preferences/KeyStoreEncryption.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/preferences/KeyStoreEncryption.kt @@ -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 + } } } diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/marmot/MarmotManager.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/marmot/MarmotManager.kt index bbf635fae..027c28535 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/marmot/MarmotManager.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/marmot/MarmotManager.kt @@ -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 } diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/marmot/mls/group/MlsGroupManager.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/marmot/mls/group/MlsGroupManager.kt index 952e633ed..7a8921a57 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/marmot/mls/group/MlsGroupManager.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/marmot/mls/group/MlsGroupManager.kt @@ -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.