android: USB hardening from device logs - async stream reader, CLEAR_HALT recovery, session mutex, detach handling, fast init

2026-09-10 01:21:29 +08:00
parent dbb4f24608
commit 0f2aa11196
5 changed files with 229 additions and 59 deletions
@@ -99,7 +99,7 @@ fun LiveScreen(vm: LiveViewModel = viewModel(), onOpenGallery: () -> Unit = {})
                },
        )

-        if (!state.connected) {
+        if (!state.connected || state.status == "no_stream_data") {
            Text(
                text = statusText(state),
                modifier = Modifier
@@ -296,6 +296,7 @@ private fun statusText(state: LiveViewModel.LiveState): String = when (state.sta
    "open_fail" -> "USB打开失败（查看调试日志）"
    "no_endpoints" -> "未找到数据端点（查看调试日志）"
    "connect_fail" -> "连接流程异常（查看调试日志）"
+    "no_stream_data" -> "已连接但无数据流（10秒），日志已记录"
    else -> {
        val prefix = if (state.status.startsWith("exception:")) {
            "异常：" + state.status.removePrefix("exception:")
@@ -76,10 +76,14 @@ class LiveViewModel(app: Application) : AndroidViewModel(app) {
    @Volatile
    private var framesRcvd = 0

+    private var usbDetachReceiver: android.content.BroadcastReceiver? = null
+
+    private var lastConnectMs = 0L
+
    init {
        session.setListener(sessionListener)
-        // auto permission + start when the camera is plugged in while running
        val ctx = getApplication<Application>()
+        // auto permission + start when the camera is plugged in while running
        usbReceiver = object : android.content.BroadcastReceiver() {
            override fun onReceive(c: android.content.Context?, i: android.content.Intent?) {
                connect()
@@ -90,6 +94,36 @@ class LiveViewModel(app: Application) : AndroidViewModel(app) {
            android.content.IntentFilter(android.hardware.usb.UsbManager.ACTION_USB_DEVICE_ATTACHED),
            if (android.os.Build.VERSION.SDK_INT >= 33) android.content.Context.RECEIVER_NOT_EXPORTED else 0,
        )
+        // camera re-enumerates (power blip / reboot): release the dead session
+        usbDetachReceiver = object : android.content.BroadcastReceiver() {
+            override fun onReceive(c: android.content.Context?, i: android.content.Intent?) {
+                val dev: android.hardware.usb.UsbDevice? = if (android.os.Build.VERSION.SDK_INT >= 33) {
+                    i?.getParcelableExtra(
+                        android.hardware.usb.UsbManager.EXTRA_DEVICE,
+                        android.hardware.usb.UsbDevice::class.java,
+                    )
+                } else {
+                    @Suppress("DEPRECATION")
+                    i?.getParcelableExtra(android.hardware.usb.UsbManager.EXTRA_DEVICE)
+                }
+                com.mag160c.thermal.media.DebugLog.log(
+                    "vm", "usb detached vid=0x%04X".format(java.util.Locale.US, dev?.vendorId ?: 0),
+                )
+                if (dev?.vendorId == 0x833C) {
+                    session.stop()
+                    _state.value = _state.value.copy(
+                        connected = false,
+                        streaming = false,
+                        status = "no_device",
+                    )
+                }
+            }
+        }
+        ctx.registerReceiver(
+            usbDetachReceiver,
+            android.content.IntentFilter(android.hardware.usb.UsbManager.ACTION_USB_DEVICE_DETACHED),
+            if (android.os.Build.VERSION.SDK_INT >= 33) android.content.Context.RECEIVER_NOT_EXPORTED else 0,
+        )
        // push frames into the MP4 recorder while recording
        session.recorderHook = { argb ->
            val rec = recorder
@@ -103,6 +137,12 @@ class LiveViewModel(app: Application) : AndroidViewModel(app) {

    /** Begin USB permission flow, then start streaming. No device -> idle notice. */
    fun connect() {
+        val now = android.os.SystemClock.elapsedRealtime()
+        if (now - lastConnectMs < 800) {
+            com.mag160c.thermal.media.DebugLog.log("vm", "connect() debounced")
+            return
+        }
+        lastConnectMs = now
        try {
            com.mag160c.thermal.media.DebugLog.log("vm", "connect()")
            val context = getApplication<Application>()
@@ -3,6 +3,7 @@ package com.mag160c.thermal.usb
 import android.content.Context
 import android.hardware.usb.UsbDeviceConnection
 import android.hardware.usb.UsbEndpoint
+import android.hardware.usb.UsbRequest
 import com.mag160c.thermal.core.FrameStream
 import com.mag160c.thermal.core.RenderPipeline
 import com.mag160c.thermal.media.DebugLog
@@ -11,19 +12,25 @@ import kotlinx.coroutines.Dispatchers
 import kotlinx.coroutines.SupervisorJob
 import kotlinx.coroutines.cancel
 import kotlinx.coroutines.launch
+import java.nio.ByteBuffer
 import java.util.Locale
 import java.util.concurrent.atomic.AtomicBoolean

 /**
 * Live IR camera session: link -> query info -> start stream -> render.
 * Ported from csdk/src/mag160c_ir.c + the demo3 FFC cadence:
- *   prepare: 66b / 66c / 66f (4B each)
- *   start:   reader loop -> 50 ms -> FFC(0) x2 -> 300 ms -> START(73)
+ *   prepare: 66b / 66c / 66f (4B each, responses may be absent on phones)
+ *   start:   50 ms -> FFC(0) x2 -> 300 ms -> START(73)
 *   stop:    STOP(74)
- * The FFC(0)x2 + START sequence before reading is REQUIRED (verified on
- * hardware via the C reference): without it the camera never streams.
- * Sustained FFC(0)/FFC(1) commands are emitted by [RenderPipeline.onFfc]
- * (official cadence keeps the type=0 stream alive).
+ * Sustained FFC(0)/FFC(1) commands are emitted by [RenderPipeline.onFfc].
+ *
+ * Round-13 hardening from real-device logs (vivo, EP silence + re-enum):
+ *  - stream endpoint read via async UsbRequest (API 30+), sync fallback;
+ *  - every failed transfer logs the endpoint status and tries
+ *    CLEAR_FEATURE(HALT) once, then retries (Android never clears halts);
+ *  - only ONE session may own the camera (a second claimInterface steals
+ *    the interface from the first and both die);
+ *  - init command reads are short (responses are advisory, as in C).
 */
 class IrSession(context: Context) {
    data class CameraIdentity(
@@ -47,15 +54,24 @@ class IrSession(context: Context) {
        val ok: Boolean get() = written > 0 && read > 3
    }

+    companion object {
+        /** The single session allowed to own the camera across view models. */
+        @Volatile
+        private var active: IrSession? = null
+    }
+
    private val scope = CoroutineScope(SupervisorJob() + Dispatchers.IO)
    private val transport = UsbTransport(context)
    private var listener: Listener? = null
    private var pipeline: RenderPipeline? = null
    private val running = AtomicBoolean(false)
    private var streaming = false
-
    private var identity = CameraIdentity(1, 0, 160, 120, 15)

+    /** Pending async stream request (cancelled by [stop] to unblock requestWait). */
+    @Volatile
+    private var streamRequest: UsbRequest? = null
+
    fun setListener(l: Listener?) {
        listener = l
    }
@@ -100,6 +116,14 @@ class IrSession(context: Context) {

    private fun startInternal(ddtBytes: ByteArray) {
        notify(State.LINKING, null)
+        // one camera, one owner: a stale session holding the device would
+        // otherwise be robbed by our claimInterface and both would stall
+        active?.let { prev ->
+            if (prev !== this) {
+                DebugLog.log("session", "stopping stale previous session")
+                prev.stop()
+            }
+        }
        val dev = transport.findDevice()
        if (dev == null) {
            DebugLog.log("session", "no_device (VID 0x833C not in deviceList)")
@@ -121,13 +145,6 @@ class IrSession(context: Context) {
            return
        }
        val (epOut, epResp, epStream) = transport.endpoints()
-        DebugLog.log(
-            "session",
-            "endpoints out=${epOut?.let { "0x%02X".format(Locale.US, it.address) } ?: "null"} " +
-                "resp=${epResp?.let { "0x%02X".format(Locale.US, it.address) } ?: "null"} " +
-                "stream=${epStream?.let { "0x%02X".format(Locale.US, it.address) } ?: "null"} " +
-                "maxPkt=${epStream?.maxPacketSize}",
-        )
        if (epOut == null || epResp == null || epStream == null) {
            transport.close()
            notify(State.ERROR, "no_endpoints")
@@ -135,7 +152,9 @@ class IrSession(context: Context) {
        }
        val pipe = RenderPipeline(
            w = identity.width, h = identity.height,
-            onFfc = { param -> sendCmd(cmd8(MagProtocol.CMD_FFC, param), epOut, epResp, "FFC($param)") },
+            onFfc = { param ->
+                sendCmd(cmd8(MagProtocol.CMD_FFC, param), epOut, epResp, "FFC($param)")
+            },
        )
        if (!pipe.loadDdt(ddtBytes)) {
            DebugLog.log("session", "ddt_fail size=${ddtBytes.size}")
@@ -145,11 +164,13 @@ class IrSession(context: Context) {
        }
        DebugLog.log("session", "ddt loaded ${ddtBytes.size} bytes")
        pipeline = pipe
+        active = this

-        // prepare sequence (verified hardware: 4-byte commands)
-        sendCmd(cmd4(MagProtocol.CMD_PREPARE1), epOut, epResp, "66b")
-        sendCmd(cmd4(MagProtocol.CMD_PREPARE2), epOut, epResp, "66c")
-        sendCmd(cmd4(MagProtocol.CMD_GET_INFO), epOut, epResp, "66f")
+        // prepare sequence (verified hardware: 4-byte commands; responses
+        // advisory — the C reference ignores them, so short reads here)
+        sendCmd(cmd4(MagProtocol.CMD_PREPARE1), epOut, epResp, "66b", 400)
+        sendCmd(cmd4(MagProtocol.CMD_PREPARE2), epOut, epResp, "66c", 400)
+        sendCmd(cmd4(MagProtocol.CMD_GET_INFO), epOut, epResp, "66f", 400)
        notify(State.STREAMING, null)
        notifyIdentity()
        DebugLog.log("session", "identity $identity")
@@ -159,13 +180,10 @@ class IrSession(context: Context) {
        // camera never streams (root cause of the round-11 black screen).
        running.set(true)
        Thread.sleep(50)
-        sendCmd(cmd8(MagProtocol.CMD_FFC, 0), epOut, epResp, "FFC(0) pre-start 1/2")
-        sendCmd(cmd8(MagProtocol.CMD_FFC, 0), epOut, epResp, "FFC(0) pre-start 2/2")
+        sendCmd(cmd8(MagProtocol.CMD_FFC, 0), epOut, epResp, "FFC(0) pre-start 1/2", 400)
+        sendCmd(cmd8(MagProtocol.CMD_FFC, 0), epOut, epResp, "FFC(0) pre-start 2/2", 400)
        Thread.sleep(300)
-        val st = sendCmd(cmd4(MagProtocol.CMD_START), epOut, epResp, "START")
-        if (!st.ok) {
-            DebugLog.log("session", "START rejected/ignored: $st")
-        }
+        sendCmd(cmd4(MagProtocol.CMD_START), epOut, epResp, "START", 400)
        streamLoop(pipe, epStream, epOut, epResp)
    }

@@ -181,21 +199,47 @@ class IrSession(context: Context) {
    private fun cmd4(magic: Int) = MagProtocol.cmd4(magic)
    private fun cmd8(magic: Int, param: Int) = MagProtocol.cmd8(magic, param)

-    private fun sendCmd(packet: ByteArray, out: UsbEndpoint, resp: UsbEndpoint, name: String): CmdResult {
+    /** Log endpoint status + clear a possible halt; returns clear rc. */
+    private fun diagnoseEndpoint(conn: UsbDeviceConnection, epAddr: Int) {
+        val st = ByteArray(2)
+        val src = conn.controlTransfer(0x80, 0, 0, epAddr, st, 2, 100)
+        val halted = if (src == 2) (st[0].toInt() and 0x01) else -1
+        val clr = conn.controlTransfer(0x02, 1, 0, epAddr, null, 0, 100)
+        DebugLog.log(
+            "usb",
+            "ep 0x%02X get_status rc=%d halted=%d clear_halt rc=%d".format(
+                Locale.US, epAddr, src, halted, clr,
+            ),
+        )
+    }
+
+    private fun sendCmd(
+        packet: ByteArray,
+        out: UsbEndpoint,
+        resp: UsbEndpoint,
+        name: String,
+        respTimeoutMs: Int = 2000,
+    ): CmdResult {
        val conn: UsbDeviceConnection = transport.connection()
            ?: run {
                DebugLog.log("cmd", "$name: no connection")
                return CmdResult(0, 0, 0)
            }
-        val written = conn.bulkTransfer(out, packet, packet.size, 500)
+        var written = conn.bulkTransfer(out, packet, packet.size, 500)
        if (written != packet.size) {
-            DebugLog.log("cmd", "$name write=$written/${packet.size} (EP 0x03)")
+            DebugLog.log("cmd", "$name write=$written/${packet.size} -> diagnose + retry")
+            diagnoseEndpoint(conn, out.address)
+            written = conn.bulkTransfer(out, packet, packet.size, 500)
+            if (written != packet.size) {
+                DebugLog.log("cmd", "$name retry write=$written (EP 0x03 dead)")
                return CmdResult(written, 0, 0)
            }
+        }
        val buf = ByteArray(0x1000)
-        val n = conn.bulkTransfer(resp, buf, buf.size, 2000)
+        val n = conn.bulkTransfer(resp, buf, buf.size, respTimeoutMs)
        if (n <= 3) {
-            DebugLog.log("cmd", "$name read=$n bytes (EP 0x82, timeout 2000 ms)")
+            diagnoseEndpoint(conn, resp.address)
+            DebugLog.log("cmd", "$name read=$n bytes (EP 0x82, ${respTimeoutMs} ms)")
            return CmdResult(written, n, 0)
        }
        val magic = MagProtocol.u32(buf, 0)
@@ -239,38 +283,86 @@ class IrSession(context: Context) {
        val out = IntArray(320 * 240)
        val tmp = ByteArray(0x8000)
        val noop = ByteArray(0)
+
+        // async stream reader on API 30+ (sync bulkTransfer proved unreliable
+        // on the vivo build: zero stream bytes); sync fallback below API 30
+        val async = android.os.Build.VERSION.SDK_INT >= 30
+        val bb = if (async) ByteBuffer.allocateDirect(tmp.size) else null
+        if (async && bb != null) {
+            val req = UsbRequest()
+            if (req.initialize(conn, epStream) && req.queue(bb)) {
+                streamRequest = req
+                DebugLog.log(
+                    "stream",
+                    "reader loop start: async UsbRequest on EP 0x%02X".format(
+                        Locale.US, epStream.address,
+                    ),
+                )
+            } else {
+                DebugLog.log("stream", "async init failed -> sync bulkTransfer fallback")
+            }
+        } else {
+            DebugLog.log("stream", "reader loop start: sync bulkTransfer")
+        }
+
        var readCount = 0
        var frameCount = 0
        var renderCount = 0
        var timeouts = 0
-        var resyncs = 0
        val t0 = android.os.SystemClock.elapsedRealtime()
        var lastLog = t0
-        var first16 = 0
-        DebugLog.log("stream", "reader loop start (buffer 0x8000, timeout 500 ms)")
+        var firstReads = 0
+        var noDataNotified = false
+
        while (running.get()) {
-            val n = conn.bulkTransfer(epStream, tmp, tmp.size, 500)
+            val n: Int
+            val req = streamRequest
+            if (req != null && bb != null) {
+                val done = conn.requestWait()
+                if (done == null) {
+                    DebugLog.log("stream", "requestWait null (closed?)")
+                    break
+                }
+                if (done !== req) continue
+                // documented ByteBuffer contract: position = bytes transferred
+                n = bb.position()
+                if (n > 0) {
+                    bb.flip()
+                    bb.get(tmp, 0, n)
+                }
+                bb.clear()
+                if (!req.queue(bb)) {
+                    DebugLog.log("stream", "requeue failed -> diagnose + retry once")
+                    diagnoseEndpoint(conn, epStream.address)
+                    if (!req.queue(bb)) {
+                        DebugLog.log("stream", "requeue failed twice -> async off")
+                        streamRequest = null
+                    }
+                }
                if (n <= 0) {
                    timeouts++
                    continue
                }
+            } else {
+                n = conn.bulkTransfer(epStream, tmp, tmp.size, 500)
+                if (n <= 0) {
+                    timeouts++
+                    continue
+                }
+            }
            readCount++
-            if (first16 < 3) {
+            if (firstReads < 3) {
                DebugLog.log(
-                    "stream", "first reads [$first16] n=$n head=%s".format(
+                    "stream", "first reads [$firstReads] n=$n head=%s".format(
                        Locale.US,
                        tmp.copyOfRange(0, minOf(n, 24)).joinToString(" ") {
                            "%02X".format(Locale.US, it.toInt() and 0xFF)
                        },
                    ),
                )
-                first16++
+                firstReads++
            }
            var len = stream.push(tmp, n, frameBuf)
-            if (len == 0 && n > 0 && ++resyncs % 200 == 1) {
-                // lots of data but no valid frames: log a heartbeat
-                DebugLog.log("stream", "resyncing: reads=$readCount timeouts=$timeouts (no frame)")
-            }
            while (len > 0 && running.get()) {
                frameCount++
                val type = MagProtocol.u32(frameBuf, 12)
@@ -293,17 +385,18 @@ class IrSession(context: Context) {
            }
            val now = android.os.SystemClock.elapsedRealtime()
            if (now - lastLog >= 2000) {
-                val fps = frameCount * 1000f / (now - t0)
-                val last = MagProtocol.u32(frameBuf, 12)
+                val fps = frameCount * 1000f / (now - t0).coerceAtLeast(1)
                DebugLog.log(
                    "stream",
                    "stats: reads=$readCount frames=$frameCount rendered=$renderCount " +
-                        "timeouts=$timeouts fps=%.1f lastType=$last " +
-                        "renderState=${pipe.frameIndex()} ref=${pipe.hasReference()}".format(
-                            Locale.US, fps,
-                        ),
+                        "timeouts=$timeouts fps=%.1f ".format(Locale.US, fps) +
+                        "renderState=${pipe.frameIndex()} ref=${pipe.hasReference()}",
                )
                lastLog = now
+                if (readCount == 0 && now - t0 > 10000 && !noDataNotified) {
+                    noDataNotified = true
+                    notify(State.STREAMING, "no_stream_data")
+                }
            }
        }
        val secs = (android.os.SystemClock.elapsedRealtime() - t0) / 1000.0
@@ -313,7 +406,18 @@ class IrSession(context: Context) {
                Locale.US, secs,
            ),
        )
+        // teardown owned HERE (stop() only flips the flag): STOP then close,
+        // so the STOP actually reaches the camera
+        val stopReq = streamRequest
+        streamRequest = null
+        try {
+            stopReq?.cancel()
+        } catch (_: Exception) {
+        }
+        if (active === this) active = null
        sendCmd(cmd4(MagProtocol.CMD_STOP), epOut, epResp, "STOP")
+        transport.close()
+        notify(State.IDLE, null)
    }

    /** Manual FFC (official shutter button / double tap). */
@@ -340,8 +444,11 @@ class IrSession(context: Context) {
    fun stop() {
        if (!running.getAndSet(false)) return
        pipeline = null
-        transport.close()
-        notify(State.IDLE, null)
+        // unblock a pending async read so the loop can exit and tear down
+        try {
+            streamRequest?.cancel()
+        } catch (_: Exception) {
+        }
    }

    fun destroy() {
@@ -249,10 +249,32 @@
 - 注：取日志时 DCIM/MAG160C 和 Download/MAG160C 都看一眼（文件头 sink= 注明
  实际位置）；若在前者失败会自动落后者。

+## 用户反馈修复 第十三轮（2026-09-10，真机日志分析：端点静默 + 重枚举）
+
+- [x] **用户回传 debug 日志**（vivo V2509A, Android16）：相机识别/DDT/66b 响应全正常
+      （SN 160043865），但 66c/66f 响应超时、FFC/START 第一轮写失败（write=-1，
+      端点疑似 halt）、流端点 19 秒 0 字节；00:51:10 相机重新枚举（权限再次弹出）
+      ——相机在会话中途疑似断电/复位；且新旧两个 Activity 的会话同时在抢同一设备
+      （claimInterface 互相夺走）。
+- [x] **IrSession 加固**：流端点改 **UsbRequest 异步**（API30+，position=字节数；
+      低版本回退同步 bulkTransfer）；任何 transfer 失败先 GET_STATUS 诊断 +
+      **CLEAR_FEATURE(HALT)** 再重试一次；66b/66c/66f 响应读取缩短为 400ms 且
+      失败不阻断（与 C 参考一致）；**会话互斥**（companion active，新会话先停旧
+      会话）；stop() 时序修复（STOP 在 close 之前发，由 streamLoop 收尾）。
+- [x] **LiveViewModel**：注册 USB **DETACHED** 接收器（VID 匹配→停会话+no_device）；
+      connect() 800ms 去抖；流 10 秒 0 数据 notify `no_stream_data`
+      （LiveScreen 屏显"已连接但无数据流"）。
+- [x] 构建+单测全过；APK 已更新（11.87MB）。
+- ⚠️ **下一步排查（若仍无流）**：相机中途重枚举强烈怀疑 **OTG 供电不足**
+  （vivo 口限流 → 相机 MCU 帧处理起来后掉电复位）。请用户：① 换一根好点的
+  短线/带供电的 OTG 转接器再试；② 在同一台手机装官方普通版 MAG-Cx 对照
+  （若官方也掉，就是供电/兼容问题，与我们的代码无关）；③ 新日志看
+  `usb detached` 与 `get_status halted=` 行。
+
 ## 待办

- 真机USB实测（温度绝对值标定、FFC/录像/MDT保存端到端）——当前进行中：
-  第11轮日志落盘 APK 待用户回传 debug_*.log 分析
+- 真机USB实测（温度绝对值标定、FFC/录像/MDT保存端到端）——进行中：
+  第13轮加固 APK 待用户复测；若仍无流，按上方供电排查三步走
 - 网络互连远程预览（用户需求：UDP自动发现+手动IP）
 - 离线MDT温度解码（ConvertResponse2Temperature+标定参数，待真机文件对照）
 - 厂商12调色板精确提取（需运行时抓取）