fix(reconnect): 合规接收端被周期性误判「链路已死」（v0.2.2）+ 可注入计时覆盖退避封顶

一、测试抓到的真实缺陷（T-AND-017）契约 §3.6 明确：「接收端收到任何一帧都算活动，ping **无需额外应答**即可保活， pong 只用于诊断」—— 即"合规但不回 pong"的接收端是**合法**的。但 PoseWebSocketClient.onOpen 里写的是 lastPongAtMs = timing.nowMs()，于是心跳循环的守卫 if (lastPongAtMs > 0 && silentFor > limit) **恒为真**：对任何接收端都会「判定链路已死 → 主动断链 → 重连」，默认参数（heartbeatIntervalMs=5000）下即**每 15 秒断一次**，正是用户抱怨的「频繁重连」。为什么以前没暴露：我们自己的接收端（Windows PoseServer）**会**回 pong （T-WIN-020 实测 9 次 ping 全部收到 pong），这条路径在自家联调里永远走不到。修复：onOpen 复位 lastPongAtMs = 0L（0 = 本连接还没收到过 pong），只有「曾经回过 pong、之后又不回了」才判定链路已死 —— 这正是该诊断本来的意图。二、可注入计时 Timing（时钟 + 等待）契约 §7.1 的退避序列 0.5s→1→2→4→8→15s 封顶若要端到端验证，真实等待约 30 秒；「连续 3 个心跳周期没收到 pong」也要等几十秒。抽成接口后： * 生产默认 SystemTiming = 真实时钟 + 真实 delay，行为与抽取前完全一致（10 处 System.currentTimeMillis() 与 2 处 delay() 改走 timing）； * 测试注入「可控时钟 + 立即返回的等待」，毫秒级跑完整条序列。三、新增 4 项 JVM 用例（PoseWebSocketBackoffTest，无需设备） * 退避序列在 15 秒封顶且不无限增长：连续失败下断言第 1..8 次等待分别落在 500/1000/2000/4000/8000/15000/15000/15000 的 ±20% 区间内，且真实耗时 < 5 秒； * 等待走注入实现：前三次重连真实耗时 < 1.5 秒（真实退避需 3.5 秒）； * **合规但从不回 pong 的接收端不会被判定链路已死**（修复前此处失败）：走过 6 个心跳周期仍为 streaming、无「判定链路已死」日志； * 曾经回过 pong 之后停止回复时判定链路已死并重连：诊断仍然有效。实测：./gradlew :app:testDebugUnitTest → 7 个测试类 / 68 项用例 / 0 失败（原 64）。 build/verify.sh 全绿（签名、APK 元数据 0.2.2/202、native 体检、ABI、R8、dex）。版本号 0.2.1/201 → 0.2.2/202。写测试踩的两个坑（已写入任务文档）： 1. 不要在瞬时重连下读 stats.nextRetryMs（等待立即返回后已被清零，与重连循环竞争），等待时长应取注入实现记录的事实； 2. 虚拟时钟需要一个真实让出点（FakeTiming.await 里 2ms 真实 delay），否则心跳循环会在网络回调落地前把时钟推过阈值。
2026-09-18 02:34:54 +08:00
parent 6dfd90f7ca
commit c0d0937023
7 changed files with 408 additions and 21 deletions
@@ -0,0 +1,231 @@
+package com.opendance.studio
+
+import com.opendance.studio.net.PoseWebSocketClient
+import com.opendance.studio.net.ReconnectPolicy
+import com.opendance.studio.net.Timing
+import com.opendance.studio.util.ConnectionLog
+import kotlinx.coroutines.CoroutineScope
+import kotlinx.coroutines.Dispatchers
+import kotlinx.coroutines.SupervisorJob
+import kotlinx.coroutines.cancel
+import okhttp3.Response
+import okhttp3.WebSocket
+import okhttp3.WebSocketListener
+import okhttp3.mockwebserver.MockResponse
+import okhttp3.mockwebserver.MockWebServer
+import okhttp3.mockwebserver.SocketPolicy
+import org.junit.After
+import org.junit.Assert.assertEquals
+import org.junit.Assert.assertTrue
+import org.junit.Before
+import org.junit.Test
+import org.junit.runner.RunWith
+import org.robolectric.RobolectricTestRunner
+import org.robolectric.annotation.Config
+import java.util.Collections
+import java.util.concurrent.atomic.AtomicInteger
+
+/**
+ * T-AND-017：**退避封顶**与**缺 pong 判定链路已死**的端到端验证（JVM，无需设备）
+ *
+ * 为什么单有 `ReconnectPolicyTest` 不够：`ReconnectPolicy` 只是纯函数
+ * 「第 n 次应该等多久」，而契约 §7.1 真正承诺的是**整条序列**
+ * `0.5s → 1 → 2 → 4 → 8 → 15s 封顶`（之后一直是 15s）——
+ * 那需要连续 7 次失败重连，真实等待约 **30 秒**，写在集成测试里既慢又易 flaky。
+ *
+ * 因此给 [PoseWebSocketClient] 抽了一个可注入的 [Timing]
+ * （「现在几点」+「等多久」）。生产默认是真实时钟与 `delay()`，行为不变；
+ * 测试注入**可控时钟 + 立即返回的等待**，于是：
+ *   * 30 秒的退避序列可以在毫秒级跑完并逐值断言；
+ *   * 「连续 3 个心跳周期没收到 pong 就判定链路已死」也能在不等待的情况下触发。
+ */
+@RunWith(RobolectricTestRunner::class)
+@Config(sdk = [34])
+class PoseWebSocketBackoffTest {
+
+    /** 可控时钟 + 立即返回的等待：记录每次等待时长，并推进虚拟时钟 */
+    private class FakeTiming : Timing {
+        var now = 1_000_000L
+        val awaited = Collections.synchronizedList(mutableListOf<Long>())
+
+        override fun nowMs(): Long = now
+
+        override suspend fun await(delayMs: Long) {
+            awaited.add(delayMs)
+            now += delayMs.coerceAtLeast(1L)
+            // 只让出 2ms *真实*时间：网络回调（pong / welcome）需要有机会落地，
+            // 否则心跳循环会在 pong 到达之前就把虚拟时钟推过阈值。
+            // 2ms × 个位数次数，整体仍远小于真实退避的 30 秒。
+            kotlinx.coroutines.delay(2)
+        }
+
+        fun snapshot(): List<Long> = synchronized(awaited) { awaited.toList() }
+    }
+
+    private lateinit var server: MockWebServer
+    private lateinit var scope: CoroutineScope
+    private val clients = mutableListOf<PoseWebSocketClient>()
+
+    @Before
+    fun setUp() {
+        ConnectionLog.clear()
+        server = MockWebServer()
+        server.start()
+    }
+
+    @After
+    fun tearDown() {
+        clients.forEach { runCatching { it.disconnect() } }
+        scope.cancel()
+        runCatching { server.shutdown() }
+        ConnectionLog.clear()
+    }
+
+    private fun newClient(timing: Timing): PoseWebSocketClient {
+        scope = CoroutineScope(SupervisorJob() + Dispatchers.IO)
+        return PoseWebSocketClient(scope, timing = timing).also { clients.add(it) }
+    }
+
+    private fun wsUrl(): String = server.url("/pose").toString().replace("http://", "ws://")
+
+    private fun waitUntil(timeoutMs: Long = 8_000, what: String, cond: () -> Boolean) {
+        val deadline = System.currentTimeMillis() + timeoutMs
+        while (System.currentTimeMillis() < deadline) {
+            if (cond()) return
+            Thread.sleep(10)
+        }
+        throw AssertionError("等待超时（${timeoutMs}ms）：$what")
+    }
+
+    @Test
+    fun `退避序列在 15 秒封顶，且不会无限增长`() {
+        // 每个连接都直接失败：用 SocketPolicy.DISCONNECT_AT_START（升级前断开）
+        repeat(12) {
+            server.enqueue(MockResponse().setSocketPolicy(SocketPolicy.DISCONNECT_AT_START))
+        }
+        val timing = FakeTiming()
+        val client = newClient(timing)
+        val t0 = System.currentTimeMillis()
+        client.connect(wsUrl())
+
+        // 等到第 8 次重连被安排（真实等待为 0，因为 FakeTiming 立即返回）
+        waitUntil(what = "安排到第 8 次重连") { client.stats.value.reconnectAttempts >= 8 }
+        val elapsed = System.currentTimeMillis() - t0
+
+        val delays = timing.snapshot()
+        assertTrue("应记录到至少 8 次等待（实际 ${delays.size}）", delays.size >= 8)
+
+        // 契约 §7.1：min(500ms * 2^(n-1), 15000ms) × (1 ± 20%)
+        val expectedBase = listOf(500L, 1_000L, 2_000L, 4_000L, 8_000L, 15_000L, 15_000L, 15_000L)
+        for ((index, base) in expectedBase.withIndex()) {
+            val actual = delays[index]
+            val low = (base * (1 - ReconnectPolicy.JITTER_RATIO)).toLong()
+            val high = (base * (1 + ReconnectPolicy.JITTER_RATIO)).toLong()
+            assertTrue(
+                "第 ${index + 1} 次重连等待应落在 [$low, $high]（基础值 ${base}ms），实际 ${actual}ms",
+                actual in low..high,
+            )
+        }
+        assertTrue(
+            "封顶后必须一直是 15000ms（不得增长）；实测前 8 次：$delays",
+            delays.take(8).drop(5).all { it in 12_000L..18_000L },
+        )
+        assertTrue(
+            "虚拟时钟应被推着走（证明等待走的是注入实现而非真实 delay）；" +
+                "真实耗时 ${elapsed}ms 应远小于 30 秒",
+            elapsed < 5_000,
+        )
+    }
+
+    @Test
+    fun `等待走注入实现——真实 delay 不会被调用（耗时对照）`() {
+        repeat(4) { server.enqueue(MockResponse().setSocketPolicy(SocketPolicy.DISCONNECT_AT_START)) }
+        val timing = FakeTiming()
+        val client = newClient(timing)
+        val t0 = System.currentTimeMillis()
+        client.connect(wsUrl())
+        waitUntil(what = "安排到第 3 次重连") { client.stats.value.reconnectAttempts >= 3 }
+        val elapsed = System.currentTimeMillis() - t0
+        // 真实退避前三次合计 3.5 秒；注入实现下应远小于 1 秒
+        assertTrue("注入 FakeTiming 后不应真的等待（实测 ${elapsed}ms）", elapsed < 1_500)
+        // 注意：不要在瞬时重连下断言 stats.nextRetryMs —— 等待立即返回后，
+        // 客户端已经进入下一次尝试并把该字段清零，读取会与重连循环竞争（第一版就踩了）。
+        // 等待时长本身由注入实现记录，是可靠的事实来源。
+        assertTrue("注入实现应记录到等待（实际 ${timing.snapshot()}）", timing.snapshot().size >= 3)
+    }
+
+    /** 造一个只回 welcome、pong 行为可配置的接收端 */
+    private fun enqueueReceiver(replyToPings: (n: Int) -> Boolean) {
+        val pingCount = AtomicInteger(0)
+        server.enqueue(
+            MockResponse()
+                .setHeader("Sec-WebSocket-Protocol", "opendance.pose.v1")
+                .withWebSocketUpgrade(object : WebSocketListener() {
+                    override fun onMessage(webSocket: WebSocket, text: String) {
+                        when {
+                            text.contains("\"hello\"") -> webSocket.send(
+                                """{"type":"welcome","protocol":"opendance.pose.v1",""" +
+                                    """"sessionId":"s1","expectedFps":30,""" +
+                                    """"silentTimeoutMs":3000,"heartbeatIntervalMs":1000}""",
+                            )
+                            text.contains("\"ping\"") -> {
+                                if (replyToPings(pingCount.incrementAndGet())) {
+                                    webSocket.send("""{"type":"pong","sentAtMs":1,"serverAtMs":2}""")
+                                }
+                            }
+                        }
+                    }
+                }),
+        )
+    }
+
+    /**
+     * 契约 §3.6：接收端收到任何一帧都算活动，**`ping` 无需额外应答即可保活**，
+     * `pong` 只用于诊断 —— 所以"合规但不回 pong"的接收端**不能**被判定为链路已死。
+     *
+     * 这是本轮修掉的一个真实缺陷：`onOpen` 里把 `lastPongAtMs` 设成了当前时刻，
+     * 于是"连续 3 个心跳周期没收到 pong"对任何接收端都会触发 —— 默认参数下
+     * **每 15 秒主动断一次并重连**，正是用户抱怨的"频繁重连"。
+     */
+    @Test
+    fun `合规但从不回 pong 的接收端不会被判定链路已死`() {
+        enqueueReceiver { false }   // 从不回 pong
+        val timing = FakeTiming()
+        val client = newClient(timing)
+        client.connect(wsUrl())
+        waitUntil(what = "进入 streaming") { client.stats.value.state == PoseWebSocketClient.State.STREAMING }
+
+        // 让虚拟时钟走过 6 个心跳周期（远超 MISSED_PONG_LIMIT=3）
+        waitUntil(timeoutMs = 10_000, what = "心跳发出 6 次") { timing.snapshot().size >= 6 }
+        assertTrue(
+            "不应出现「判定链路已死」（契约 §3.6：pong 可选）：${ConnectionLog.entries()}",
+            ConnectionLog.entries().none { it.contains("判定链路已死") },
+        )
+        assertEquals("连接应仍然打开", PoseWebSocketClient.State.STREAMING, client.stats.value.state)
+        assertEquals("本连接一次 pong 都没收到", 0, client.stats.value.pongsReceived)
+    }
+
+    /** 反过来：曾经回过 pong、之后不回了 —— 这时"链路已死"的判断是有效的诊断。 */
+    @Test
+    fun `曾经回过 pong 之后停止回复时判定链路已死并重连`() {
+        enqueueReceiver { n -> n == 1 }   // 只在第一次回 pong
+        val timing = FakeTiming()
+        val client = newClient(timing)
+        client.connect(wsUrl())
+        waitUntil(what = "进入 streaming") { client.stats.value.state == PoseWebSocketClient.State.STREAMING }
+
+        waitUntil(timeoutMs = 10_000, what = "出现「判定链路已死」日志") {
+            ConnectionLog.entries().any { it.contains("判定链路已死") }
+        }
+        assertTrue(
+            "日志应说明是连续 ${ReconnectPolicy.MISSED_PONG_LIMIT} 个周期未收到 pong",
+            ConnectionLog.entries().any {
+                it.contains("连续 ${ReconnectPolicy.MISSED_PONG_LIMIT} 个心跳周期未收到 pong")
+            },
+        )
+        waitUntil(timeoutMs = 10_000, what = "进入重连") {
+            client.stats.value.state == PoseWebSocketClient.State.RECONNECTING ||
+                client.stats.value.reconnectAttempts > 0
+        }
+    }
+}