add PeachSync relay reconcile, room, socket, and dial diagnostics with log-capture coverage (v2.5.15)

@@ -1 +1 @@1-2.5.14\ No newline at end of file1+2.5.15\ No newline at end of file

@@ -16,8 +16,8 @@1616         applicationId "com.peachpasswords"1717         minSdk 261818         targetSdk 3519-        versionCode 24011420-        versionName "2.5.14"19+        versionCode 24011520+        versionName "2.5.15"2121 2222         testInstrumentationRunner "androidx.test.runner.AndroidJUnitRunner"2323         vectorDrawables {

@@ -27,68 +27,95 @@2727     onSyncComplete: () -> Unit,2828     report: (SyncOutcomeSummary) -> Unit = {},2929 ) {30-    val responderKeyHex = known.longTermPublicKeyHex31-        ?: throw IllegalArgumentException("known peer missing static key")32-    val responderKey = hexToPubkey(responderKeyHex)33-34-    // The capability names the room only; it grants no trust. KK proves both35-    // private keys immediately after, and a wrong room is refused there.36-    socket.send(37-        JSONObject()38-            .put("type", "PEACH_RECONNECT")39-            .put("rendezvous_id", rendezvousId)40-            .toString()41-            .toByteArray(Charsets.UTF_8),30+    PeachSyncLog.i(31+        "cloud-relay: dial — rendezvous=$rendezvousId, " +32+            "peer=${relayLogDetail(known.deviceName ?: known.deviceId)}",4233     )43-    val session = noiseKKInitiator(44-        ourStaticPrivateKey,45-        ourStaticPublicKey,46-        responderKey,47-        socket::send,48-        socket::receive,49-    )50-    // KK completed, so a peer is really there and answered. Everything past this51-    // point is a reportable outcome; everything before it is a dial into an52-    // empty room, which is the resting state of a phone, not a failure.5334     try {54-        sendSyncFrame(55-            encodePairIdentityFrame(localIdentity),56-            session::encrypt,35+        val responderKeyHex = known.longTermPublicKeyHex36+            ?: throw IllegalArgumentException("known peer missing static key")37+        val responderKey = hexToPubkey(responderKeyHex)38+39+        // The capability names the room only; it grants no trust. KK proves both40+        // private keys immediately after, and a wrong room is refused there.41+        socket.send(42+            JSONObject()43+                .put("type", "PEACH_RECONNECT")44+                .put("rendezvous_id", rendezvousId)45+                .toString()46+                .toByteArray(Charsets.UTF_8),47+        )48+        val session = noiseKKInitiator(49+            ourStaticPrivateKey,50+            ourStaticPublicKey,51+            responderKey,5752             socket::send,53+            socket::receive,5854         )59-        val theirIdentity = parsePairIdentityFrame(60-            receiveSyncFrame(socket::receive, session::decrypt),61-        )62-        require(identityMatchesAuthenticatedPeer(known, theirIdentity, responderKey)) {63-            "peer identity does not match authenticated KK key"64-        }55+        // KK completed, so a peer is really there and answered. Everything past this56+        // point is a reportable outcome; everything before it is a dial into an57+        // empty room, which is the resting state of a phone, not a failure.58+        try {59+            sendSyncFrame(60+                encodePairIdentityFrame(localIdentity),61+                session::encrypt,62+                socket::send,63+            )64+            val theirIdentity = parsePairIdentityFrame(65+                receiveSyncFrame(socket::receive, session::decrypt),66+            )67+            require(identityMatchesAuthenticatedPeer(known, theirIdentity, responderKey)) {68+                "peer identity does not match authenticated KK key"69+            }6570 66-        val vault = vaultFactory() ?: run {67-            report(SyncOutcomeSummary(reason = SyncOutcomeReason.VAULT_LOCKED))68-            return71+            val vault = vaultFactory()72+            if (vault == null) {73+                report(SyncOutcomeSummary(reason = SyncOutcomeReason.VAULT_LOCKED))74+            } else {75+                vault.bindAuthenticatedPeer(known)76+                val outcome = runSyncInitiator(77+                    SyncSession(78+                        remoteStaticPublicKey = responderKey.copyOf(),79+                        send = { plaintext -> sendSyncFrame(plaintext, session::encrypt, socket::send) },80+                        receive = { receiveSyncFrame(socket::receive, session::decrypt) },81+                        close = { socket.close() },82+                    ),83+                    vault,84+                )85+                if (outcome.status == SyncOutcomeStatus.COMPLETED) {86+                    onSyncComplete()87+                }88+                report(outcome.toSummary())89+            }90+        } catch (e: CancellationException) {91+            throw e92+        } catch (e: Exception) {93+            // Rethrown unchanged: the caller's retry loop owns what happens next.94+            // This only makes the failure sayable.95+            report(SyncOutcomeSummary(reason = classifySyncError(e.message ?: e.toString()), detail = e.message))96+            throw e97+        } finally {98+            session.close()6999         }70-        vault.bindAuthenticatedPeer(known)71-        val outcome = runSyncInitiator(72-            SyncSession(73-                remoteStaticPublicKey = responderKey.copyOf(),74-                send = { plaintext -> sendSyncFrame(plaintext, session::encrypt, socket::send) },75-                receive = { receiveSyncFrame(socket::receive, session::decrypt) },76-                close = { socket.close() },77-            ),78-            vault,79-        )80-        if (outcome.status == SyncOutcomeStatus.COMPLETED) {81-            onSyncComplete()82-        }83-        report(outcome.toSummary())84-    } catch (e: CancellationException) {85-        throw e86-    } catch (e: Exception) {87-        // Rethrown unchanged: the caller's retry loop owns what happens next.88-        // This only makes the failure sayable.89-        report(SyncOutcomeSummary(reason = classifySyncError(e.message ?: e.toString()), detail = e.message))90-        throw e91-    } finally {92-        session.close()100+        PeachSyncLog.i("cloud-relay: dial ok — rendezvous=$rendezvousId")101+    } catch (error: CancellationException) {102+        logCloudRelayDialFailure(rendezvousId, error)103+        throw error104+    } catch (error: Exception) {105+        logCloudRelayDialFailure(rendezvousId, error)106+        throw error93107     }94108 }109+110+private fun logCloudRelayDialFailure(rendezvousId: String, error: Throwable) {111+    val reason = relayLogReason(error)112+    val outcome = classifySyncError(reason)113+    val message = "cloud-relay: dial failed — rendezvous=$rendezvousId, reason=$reason"114+    when {115+        error is CancellationException -> PeachSyncLog.w(message)116+        outcome == SyncOutcomeReason.RELAY_UNREACHABLE || outcome == SyncOutcomeReason.SYNC_TIMEOUT ->117+            PeachSyncLog.w(message)118+        else -> PeachSyncLog.e(message)119+    }120+}121+

@@ -1,5 +1,6 @@11 package com.peachpasswords.sync22 3+import android.util.Log34 import com.peachpasswords.vault.VaultCrypto45 import kotlinx.coroutines.CancellationException56 import kotlinx.coroutines.CompletableDeferred@@ -24,6 +25,7 @@2425 import org.json.JSONObject2526 import java.security.MessageDigest2627 import java.util.concurrent.TimeUnit28+import java.util.concurrent.atomic.AtomicBoolean2729 import javax.inject.Inject2830 import javax.inject.Singleton2931 @@ -51,7 +53,57 @@5153 private const val DIAL_RETRY_DELAY_MS = 5_000L5254 private const val RELAY_CONNECT_TIMEOUT_MS = 10_000L5355 private const val RELAY_INBOX_CAPACITY = 856+private const val PEACH_SYNC_LOG_TAG = "PeachSync"5457 58+internal object PeachSyncLog {59+    @Volatile60+    internal var sink: (Int, String) -> Unit = ::writeToLogcat61+62+    fun i(message: String) = sink(Log.INFO, message)63+    fun w(message: String) = sink(Log.WARN, message)64+    fun e(message: String) = sink(Log.ERROR, message)65+66+    private fun writeToLogcat(priority: Int, message: String) {67+        try {68+            when (priority) {69+                Log.INFO -> Log.i(PEACH_SYNC_LOG_TAG, message)70+                Log.WARN -> Log.w(PEACH_SYNC_LOG_TAG, message)71+                else -> Log.e(PEACH_SYNC_LOG_TAG, message)72+            }73+        } catch (error: RuntimeException) {74+            // Local JVM tests link android.jar's throwing Log stub; a device75+            // never takes this branch.76+            if (!error.message.orEmpty().contains("not mocked")) throw error77+        }78+    }79+}80+81+internal fun relayLogDetail(detail: String): String =82+    detail.replace('\n', ' ').replace('\r', ' ')83+84+internal fun relayLogReason(error: Throwable): String = relayLogDetail(85+    error.message?.takeIf { it.isNotBlank() } ?: error.javaClass.simpleName,86+)87+88+internal data class RelayReconcileInventory(89+    val paired: List<PairedDevice>,90+    val eligible: List<PairedDevice>,91+)92+93+internal fun logRelayReconcileInventory(94+    deviceStore: PairedDeviceRegistry,95+): RelayReconcileInventory {96+    val paired = deviceStore.getAll()97+    val eligible = foregroundSyncPeers(paired)98+    PeachSyncLog.i(99+        "cloud-relay: reconcile start — ${paired.size} paired device(s), ${eligible.size} eligible",100+    )101+    if (eligible.isEmpty()) {102+        PeachSyncLog.i("cloud-relay: reconcile — no eligible peers")103+    }104+    return RelayReconcileInventory(paired, eligible)105+}106+55107 /**56108  * Keeps one socket open in each paired peer's live rendezvous rooms. The57109  * Cloudflare relay is only a splice, so being in the room is all either side@@ -76,6 +128,7 @@76128      * nothing at all.77129      */78130     private val reconcileNow = Channel<Unit>(Channel.CONFLATED)131+    private val reconcileRequested = AtomicBoolean(false)79132     private var retainedPrivateKey: ByteArray? = null80133     private var retainedPublicKey: ByteArray? = null81134 @@ -94,6 +147,9 @@94147         supervisor = scope.launch(Dispatchers.IO) {95148             try {96149                 while (isActive) {150+                    if (reconcileRequested.getAndSet(false)) {151+                        PeachSyncLog.i("cloud-relay: reconcile requested")152+                    }97153                     reconcile(98154                         this,99155                         privateKey,@@ -112,6 +168,7 @@112168 113169     /** Re-read the device list at once instead of on the next interval. */114170     fun requestReconcile() {171+        reconcileRequested.set(true)115172         reconcileNow.trySend(Unit)116173     }117174 @@ -153,6 +210,8 @@153210         localIdentity: LocalDeviceIdentity,154211         vaultFactory: () -> SyncVaultAdapter?,155212     ) {213+        val inventory = logRelayReconcileInventory(deviceStore)214+        val noEligiblePeers = inventory.eligible.isEmpty()156215         val meshRelayUrl = when (val decision = relaySettings.relayInForce()) {157216             is RelayDecision.Refuse -> {158217                 watchers.values.forEach(Job::cancel)@@ -171,10 +230,16 @@171230             is RelayDecision.Dial -> decision.relayUrl172231         }173232 233+        if (noEligiblePeers) {234+            watchers.values.forEach(Job::cancel)235+            watchers.clear()236+            return237+        }238+174239         val now = System.currentTimeMillis() / 1000L175240         val ourKeyHex = pubkeyToHex(publicKey)176241         val desired = buildMap {177-            for (device in deviceStore.getAll()) {242+            for (device in inventory.paired) {178243                 val secret = device.rendezvousSecretHex179244                     ?.let { runCatching { Rendezvous.secretFromHex(it) }.getOrNull() }180245                     ?: continue@@ -190,7 +255,18 @@190255                     else Rendezvous.waitingIds(secret, now)191256                 for (rendezvousId in ids) {192257                     val key = "${device.deviceId}|$relayUrl|$rendezvousId"193-                    put(key, RelayWaitTarget(device.deviceId, relayUrl, rendezvousId, weDial))258+                    put(259+                        key,260+                        RelayWaitTarget(261+                            deviceId = device.deviceId,262+                            deviceName = device.deviceName,263+                            deviceType = device.deviceType,264+                            trustSource = device.trustSource,265+                            relayUrl = relayUrl,266+                            rendezvousId = rendezvousId,267+                            weDial = weDial,268+                        ),269+                    )194270                 }195271             }196272         }@@ -203,14 +279,32 @@203279         }204280         for ((key, target) in desired) {205281             if (watchers[key]?.isActive == true) continue282+            val deviceDescription = relayDeviceDescription(target)206283             watchers[key] = scope.launch {207284                 while (isActive) {208285                     runCatching {209286                         val known = deviceStore.get(target.deviceId)210287                             ?: throw IllegalStateException("relay peer was unpaired")211-                        val socket = OkHttpRelaySocket.connect(212-                            Rendezvous.buildUrl(target.relayUrl, target.rendezvousId),288+                        PeachSyncLog.i(289+                            "cloud-relay: open — device=$deviceDescription, " +290+                                "relay=${target.relayUrl}, rendezvous=${target.rendezvousId}, " +291+                                "role=${if (target.weDial) "dialer" else "waiter"}",213292                         )293+                        val socket = try {294+                            OkHttpRelaySocket.connect(295+                                Rendezvous.buildUrl(target.relayUrl, target.rendezvousId),296+                            )297+                        } catch (error: Throwable) {298+                            PeachSyncLog.w(299+                                "cloud-relay: open failed — rendezvous=${target.rendezvousId}, " +300+                                    "reason=${relayLogReason(error)}",301+                            )302+                            throw error303+                        }304+                        PeachSyncLog.i(305+                            "cloud-relay: open ok — rendezvous=${target.rendezvousId}",306+                        )307+                        var closeError: Throwable? = null214308                         try {215309                             if (target.weDial) {216310                                 // A dialler that arrived before its peer had@@ -235,10 +329,14 @@235329                                             report = syncOutcomes::report,236330                                         )237331                                     }238-                                } catch (_: TimeoutCancellationException) {332+                                } catch (timeout: TimeoutCancellationException) {333+                                    closeError = timeout239334                                     reportDialUnanswered()240335                                 }241336                             } else {337+                                PeachSyncLog.i(338+                                    "cloud-relay: wait — rendezvous=${target.rendezvousId}",339+                                )242340                                 runCloudRelayResponderSession(243341                                     socket = socket,244342                                     known = known,@@ -253,8 +351,18 @@253351                                     report = syncOutcomes::report,254352                                 )255353                             }354+                        } catch (error: Throwable) {355+                            closeError = error356+                            throw error256357                         } finally {257-                            socket.close()358+                            try {359+                                socket.close()360+                            } catch (error: Throwable) {361+                                if (closeError == null) closeError = error362+                                throw error363+                            } finally {364+                                logRelaySocketClosed(target.rendezvousId, closeError)365+                            }258366                         }259367                     }260368                     delay(if (target.weDial) DIAL_RETRY_DELAY_MS else RETRY_DELAY_MS)@@ -266,11 +374,32 @@266374 267375 private data class RelayWaitTarget(268376     val deviceId: String,377+    val deviceName: String?,378+    val deviceType: String?,379+    val trustSource: String?,269380     val relayUrl: String,270381     val rendezvousId: String,271382     val weDial: Boolean,272383 )273384 385+private fun relayDeviceDescription(target: RelayWaitTarget): String =386+    "${relayLogDetail(target.deviceName ?: target.deviceId)}" +387+        "[type=${relayLogDetail(target.deviceType ?: "unset")}," +388+        "trust=${relayLogDetail(target.trustSource ?: "unset")}]"389+390+private fun logRelaySocketClosed(rendezvousId: String, error: Throwable?) {391+    val reason = error?.let(::relayLogReason) ?: "relay session complete"392+    val outcome = error?.let { classifySyncError(reason) }393+    val message = "cloud-relay: socket closed — rendezvous=$rendezvousId, reason=$reason"394+    when {395+        error == null -> PeachSyncLog.i(message)396+        error is CancellationException && error !is TimeoutCancellationException -> PeachSyncLog.i(message)397+        outcome == SyncOutcomeReason.RELAY_UNREACHABLE || outcome == SyncOutcomeReason.SYNC_TIMEOUT ->398+            PeachSyncLog.w(message)399+        else -> PeachSyncLog.e(message)400+    }401+}402+274403 internal interface RelayBinarySocket {275404     fun send(frame: ByteArray)276405     suspend fun receive(): ByteArray@@ -408,7 +537,10 @@408537             }409538 410539             override fun onClosed(webSocket: WebSocket, code: Int, reason: String) {411-                incoming.close(IllegalStateException("relay_closed_$code"))540+                val detail = reason.takeIf { it.isNotBlank() }541+                    ?.let(::relayLogDetail)542+                    ?: "no reason"543+                incoming.close(IllegalStateException("relay_closed_$code: $detail"))412544             }413545 414546             override fun onFailure(webSocket: WebSocket, t: Throwable, response: Response?) {

@@ -1,5 +1,6 @@11 package com.peachpasswords.sync22 3+import android.util.Log34 import kotlinx.coroutines.Dispatchers45 import kotlinx.coroutines.async56 import kotlinx.coroutines.channels.Channel@@ -86,37 +87,91 @@8687         var dialerSynced = false8788         var waiterSynced = false8889 89-        val waiter = async(Dispatchers.Default) {90-            runCloudRelayResponderSession(91-                socket = waiterSocket,92-                known = dialerAsSeenByWaiter,93-                registeredRendezvousId = rendezvousId,94-                ourStaticPrivateKey = waiterKeys.privateKey,95-                ourStaticPublicKey = waiterKeys.publicKey,96-                localIdentity = waiterIdentity,97-                vaultFactory = { null },98-                onSyncComplete = { waiterSynced = true },99-            )100-        }101-        val dialer = async(Dispatchers.Default) {102-            runCloudRelayInitiatorSession(103-                socket = dialerSocket,104-                known = waiterAsSeenByDialer,105-                rendezvousId = rendezvousId,106-                ourStaticPrivateKey = dialerKeys.privateKey,107-                ourStaticPublicKey = dialerKeys.publicKey,108-                localIdentity = dialerIdentity,109-                vaultFactory = { null },110-                onSyncComplete = { dialerSynced = true },111-            )112-        }90+        val logs = capturePeachSyncLogs {91+            val waiter = async(Dispatchers.Default) {92+                runCloudRelayResponderSession(93+                    socket = waiterSocket,94+                    known = dialerAsSeenByWaiter,95+                    registeredRendezvousId = rendezvousId,96+                    ourStaticPrivateKey = waiterKeys.privateKey,97+                    ourStaticPublicKey = waiterKeys.publicKey,98+                    localIdentity = waiterIdentity,99+                    vaultFactory = { null },100+                    onSyncComplete = { waiterSynced = true },101+                )102+            }103+            val dialer = async(Dispatchers.Default) {104+                runCloudRelayInitiatorSession(105+                    socket = dialerSocket,106+                    known = waiterAsSeenByDialer,107+                    rendezvousId = rendezvousId,108+                    ourStaticPrivateKey = dialerKeys.privateKey,109+                    ourStaticPublicKey = dialerKeys.publicKey,110+                    localIdentity = dialerIdentity,111+                    vaultFactory = { null },112+                    onSyncComplete = { dialerSynced = true },113+                )114+            }113115 114-        waiter.await()115-        dialer.await()116+            waiter.await()117+            dialer.await()118+        }119+        assertTrue(120+            logs.contains(121+                Log.INFO to "cloud-relay: dial — rendezvous=$rendezvousId, peer=Tablet",122+            ),123+        )124+        assertTrue(125+            logs.contains(126+                Log.INFO to "cloud-relay: dial ok — rendezvous=$rendezvousId",127+            ),128+        )116129         // No vault adapter on either side, so the handshake completes and the117130         // sync exchange is skipped — the wire is what is under test here.118131         assertFalse(dialerSynced)119132         assertFalse(waiterSynced)133+    }134+135+    @Test136+    fun `dial failure logs the rendezvous and underlying reason`() = runBlocking {137+        val dialerKeys = keys()138+        val rendezvousId = "ROOM-FAILED"139+        val socket = object : RelayBinarySocket {140+            override fun send(frame: ByteArray) = error("not reached")141+            override suspend fun receive(): ByteArray = error("not reached")142+            override fun close(code: Int, reason: String) = Unit143+        }144+        var failure: Throwable? = null145+146+        val logs = capturePeachSyncLogs {147+            failure = runCatching {148+                runCloudRelayInitiatorSession(149+                    socket = socket,150+                    known = PairedDevice(151+                        deviceId = "waiter",152+                        deviceName = "Tablet",153+                        deviceType = "android",154+                        pairedAt = 1L,155+                    ),156+                    rendezvousId = rendezvousId,157+                    ourStaticPrivateKey = dialerKeys.privateKey,158+                    ourStaticPublicKey = dialerKeys.publicKey,159+                    localIdentity = identity("dialer", "Fold", pubkeyToHex(dialerKeys.publicKey)),160+                    vaultFactory = { null },161+                    onSyncComplete = {},162+                )163+            }.exceptionOrNull()164+        }165+166+        assertEquals("known peer missing static key", failure?.message)167+        assertEquals(168+            listOf(169+                Log.INFO to "cloud-relay: dial — rendezvous=$rendezvousId, peer=Tablet",170+                Log.ERROR to "cloud-relay: dial failed — rendezvous=$rendezvousId, " +171+                    "reason=known peer missing static key",172+            ),173+            logs,174+        )120175     }121176 122177     @Test

@@ -1,9 +1,12 @@11 package com.peachpasswords.sync22 3+import android.util.Log4+import kotlinx.coroutines.CoroutineScope35 import kotlinx.coroutines.Dispatchers46 import kotlinx.coroutines.async57 import kotlinx.coroutines.awaitCancellation68 import kotlinx.coroutines.channels.Channel9+import kotlinx.coroutines.coroutineScope710 import kotlinx.coroutines.launch811 import kotlinx.coroutines.runBlocking912 import kotlinx.coroutines.test.runTest@@ -14,6 +17,7 @@1417 import org.junit.Assert.assertTrue1518 import org.junit.Test1619 import java.security.SecureRandom20+import java.util.concurrent.CopyOnWriteArrayList1721 1822 /** Enough of a vault to send SYNC_HELLO; the peer stalls before anything else. */1923 private object SilentPeerVault : SyncVaultAdapter {@@ -27,7 +31,51 @@2731     override suspend fun applyTombstones(tombstones: Map<String, Long>) {}2832 }2933 34+internal suspend fun capturePeachSyncLogs(35+    block: suspend CoroutineScope.() -> Unit,36+): List<Pair<Int, String>> = coroutineScope {37+    val events = CopyOnWriteArrayList<Pair<Int, String>>()38+    val previousSink = PeachSyncLog.sink39+    PeachSyncLog.sink = { priority, message -> events += priority to message }40+    try {41+        block()42+        events.toList()43+    } finally {44+        PeachSyncLog.sink = previousSink45+    }46+}47+3048 class CloudRelayReconnectListenerTest {49+    @Test50+    fun `reconcile logs paired and eligible counts when no peer passes the filter`() = runBlocking {51+        val devices = listOf(52+            PairedDevice(53+                deviceId = "old-desktop",54+                deviceName = "Old desktop",55+                deviceType = "desktop",56+                trustSource = "direct",57+                pairedAt = 1L,58+            ),59+        )60+        val fakeDeviceStore = object : PairedDeviceRegistry {61+            override fun getAll() = devices62+            override fun get(id: String) = devices.firstOrNull { it.deviceId == id }63+            override fun upsert(device: PairedDevice) = Unit64+        }65+66+        val logs = capturePeachSyncLogs {67+            logRelayReconcileInventory(fakeDeviceStore)68+        }69+70+        assertEquals(71+            listOf(72+                Log.INFO to "cloud-relay: reconcile start — 1 paired device(s), 0 eligible",73+                Log.INFO to "cloud-relay: reconcile — no eligible peers",74+            ),75+            logs,76+        )77+    }78+3179     private data class KeyPair(val publicKey: ByteArray, val privateKey: ByteArray)3280 3381     private fun keys(): KeyPair {