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.