mirror of
https://github.com/d4rken-org/capod.git
synced 2026-09-14 18:26:11 -04:00
feat(aap): Add structured HID descriptor logging with batched summaries
During case transitions, AirPods send 800+ cmd 0x0017 HID frames in ~20s. Previously each logged identically at VERBOSE with raw hex (~160KB noise). Now a HidTracker classifies frames (service directory, descriptor bulk, terminator) and batches consecutive bulk frames by (phase, fill), emitting 3-4 summary lines instead of 822.
This commit is contained in:
darken
@@ -49,6 +49,7 @@ internal class AapSessionEngine(
|
||||
val stemPressEvents: SharedFlow<StemPressEvent> = _stemPressEvents.asSharedFlow()
|
||||
|
||||
private val coordinator = AapSettingsCoordinator(timeSource)
|
||||
private val hidTracker = HidTracker { msg -> log(TAG) { msg } }
|
||||
private val sendMutex = Mutex()
|
||||
|
||||
private var scope: CoroutineScope? = null
|
||||
@@ -81,6 +82,8 @@ internal class AapSessionEngine(
|
||||
ancDebounceJob?.cancel()
|
||||
ancDebounceJob = null
|
||||
coordinator.clear()
|
||||
hidTracker.flush()
|
||||
hidTracker.reset()
|
||||
scope = null
|
||||
lastSentCommand = null
|
||||
lastSentAt = 0L
|
||||
@@ -175,8 +178,14 @@ internal class AapSessionEngine(
|
||||
// ── Message processing ──────────────────────────────────
|
||||
|
||||
fun processMessage(message: AapMessage) {
|
||||
val hex = message.raw.joinToString(" ") { "%02X".format(it) }
|
||||
log(TAG, VERBOSE) { "MSG cmd=0x${"%04X".format(message.commandType)} len=${message.raw.size} raw=$hex" }
|
||||
// Suppress per-frame raw hex for 0x0017 — the HidTracker emits structured summaries instead.
|
||||
// For all other commands, log at VERBOSE as before.
|
||||
if (message.commandType != CMD_HID_DESCRIPTOR) {
|
||||
val hex = message.raw.joinToString(" ") { "%02X".format(it) }
|
||||
log(TAG, VERBOSE) { "MSG cmd=0x${"%04X".format(message.commandType)} len=${message.raw.size} raw=$hex" }
|
||||
// Flush any pending HID batch summary before processing a non-HID message.
|
||||
hidTracker.flush()
|
||||
}
|
||||
|
||||
// HANDSHAKING → READY: first non-settings-echo message means the device is talking.
|
||||
// Must happen before any early returns so decoded messages (battery, stem, etc.) also trigger it.
|
||||
@@ -188,6 +197,15 @@ internal class AapSessionEngine(
|
||||
log(TAG) { "Connection READY" }
|
||||
}
|
||||
|
||||
// Fast-path for HID descriptor frames (cmd 0x0017). During case transitions, 800+ frames
|
||||
// arrive in ~20 seconds. Handle them before any profile.decode*() calls to avoid 800 wasted
|
||||
// decode attempts. The HidTracker batches bulk frames and emits structured summaries.
|
||||
if (message.commandType == CMD_HID_DESCRIPTOR) {
|
||||
hidTracker.consume(message.payload)
|
||||
_state.value = _state.value.copy(lastMessageAt = timeSource.now())
|
||||
return
|
||||
}
|
||||
|
||||
// Issue #173 diagnostic dump
|
||||
if (message.commandType == 0x001D) {
|
||||
val segments = describeDeviceInfoSegments(message.payload)
|
||||
@@ -422,9 +440,10 @@ internal class AapSessionEngine(
|
||||
|
||||
companion object {
|
||||
private val TAG = logTag("AAP", "Engine")
|
||||
private const val CMD_HID_DESCRIPTOR = 0x0017
|
||||
|
||||
private val KNOWN_NON_SETTINGS_COMMANDS = setOf(
|
||||
0x0000, 0x0002, 0x0017, 0x002B, 0x004E, 0x0052, 0x0055, 0x0057,
|
||||
0x0000, 0x0002, 0x002B, 0x004E, 0x0052, 0x0055, 0x0057,
|
||||
)
|
||||
|
||||
/**
|
||||
@@ -490,6 +509,132 @@ internal class AapSessionEngine(
|
||||
}
|
||||
}
|
||||
|
||||
// ── HID descriptor frame tracker ───────────────────────
|
||||
|
||||
/**
|
||||
* Batches cmd 0x0017 HID descriptor frames and emits structured summaries.
|
||||
*
|
||||
* During case transitions AirPods send 800+ descriptor frames in ~20 seconds.
|
||||
* Instead of logging each one, this tracker classifies each frame and batches
|
||||
* consecutive bulk descriptor frames by (phase, fill), emitting a single summary
|
||||
* line per batch.
|
||||
*/
|
||||
internal class HidTracker(private val log: (String) -> Unit) {
|
||||
|
||||
private var bulkCount = 0
|
||||
private var bulkPhase: Int = -1
|
||||
private var bulkFill: Int = -1
|
||||
|
||||
fun consume(payload: ByteArray) {
|
||||
when (val type = classify(payload)) {
|
||||
is HidFrameType.ServiceDirectory -> {
|
||||
flush()
|
||||
val names = type.services.joinToString(", ")
|
||||
log("HID: services=[$names] (${payload.size}B)")
|
||||
}
|
||||
|
||||
is HidFrameType.Descriptor -> {
|
||||
if (type.phase != bulkPhase || type.fill != bulkFill) {
|
||||
flush()
|
||||
bulkPhase = type.phase
|
||||
bulkFill = type.fill
|
||||
}
|
||||
bulkCount++
|
||||
}
|
||||
|
||||
is HidFrameType.Terminator -> {
|
||||
flush()
|
||||
log("HID: terminator (${payload.size}B)")
|
||||
}
|
||||
|
||||
is HidFrameType.Other -> {
|
||||
flush()
|
||||
val hex = payload.joinToString(" ") { "%02X".format(it) }
|
||||
log("HID: unknown (${payload.size}B) [$hex]")
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fun flush() {
|
||||
if (bulkCount > 0) {
|
||||
log("HID: $bulkCount descriptor frames phase=0x${"%02X".format(bulkPhase)} fill=0x${"%02X".format(bulkFill)}")
|
||||
bulkCount = 0
|
||||
bulkPhase = -1
|
||||
bulkFill = -1
|
||||
}
|
||||
}
|
||||
|
||||
fun reset() {
|
||||
bulkCount = 0
|
||||
bulkPhase = -1
|
||||
bulkFill = -1
|
||||
}
|
||||
|
||||
internal sealed class HidFrameType {
|
||||
data class ServiceDirectory(val services: List<String>) : HidFrameType()
|
||||
data class Descriptor(val phase: Int, val fill: Int) : HidFrameType()
|
||||
data class Terminator(val payloadSize: Int) : HidFrameType()
|
||||
data class Other(val payloadSize: Int) : HidFrameType()
|
||||
}
|
||||
|
||||
internal companion object {
|
||||
private val TERMINATOR = byteArrayOf(0x00, 0x04, 0x00, 0x00, 0x01, 0x00, 0xFF.toByte())
|
||||
private val DESCRIPTOR_PREFIX = byteArrayOf(0x00, 0x04, 0x00, 0x00, 0x44, 0x00, 0x01)
|
||||
|
||||
internal fun classify(payload: ByteArray): HidFrameType {
|
||||
if (payload.size == 7 && payload.contentEquals(TERMINATOR)) {
|
||||
return HidFrameType.Terminator(payload.size)
|
||||
}
|
||||
|
||||
if (payload.size >= 10 && payload.startsWith(DESCRIPTOR_PREFIX)) {
|
||||
val phase = payload[8].toInt() and 0xFF
|
||||
val fill = payload[9].toInt() and 0xFF
|
||||
return HidFrameType.Descriptor(phase, fill)
|
||||
}
|
||||
|
||||
if (payload.isNotEmpty() && (payload[0].toInt() and 0xFF) == 0xFE) {
|
||||
val services = parseServiceNames(payload)
|
||||
return HidFrameType.ServiceDirectory(services)
|
||||
}
|
||||
|
||||
return HidFrameType.Other(payload.size)
|
||||
}
|
||||
|
||||
/**
|
||||
* Extract service names from a directory frame by scanning for runs of printable
|
||||
* ASCII (0x20-0x7E) of length >= 2, starting from byte 4. The count at byte 3
|
||||
* is compared to the extracted names and a warning is logged on mismatch.
|
||||
*/
|
||||
private fun parseServiceNames(payload: ByteArray): List<String> {
|
||||
if (payload.size < 5) return emptyList()
|
||||
|
||||
val names = mutableListOf<String>()
|
||||
var i = 4
|
||||
while (i < payload.size) {
|
||||
val b = payload[i].toInt() and 0xFF
|
||||
if (b in 0x20..0x7E) {
|
||||
val start = i
|
||||
while (i < payload.size && (payload[i].toInt() and 0xFF) in 0x20..0x7E) i++
|
||||
if (i - start >= 2) {
|
||||
names.add(String(payload, start, i - start, Charsets.US_ASCII))
|
||||
}
|
||||
} else {
|
||||
i++
|
||||
}
|
||||
}
|
||||
return names
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
private fun ByteArray.startsWith(prefix: ByteArray): Boolean {
|
||||
if (size < prefix.size) return false
|
||||
for (i in prefix.indices) {
|
||||
if (this[i] != prefix[i]) return false
|
||||
}
|
||||
return true
|
||||
}
|
||||
|
||||
// ── Extension helpers ───────────────────────────────────
|
||||
|
||||
/** Apple wire-format boolean: 0x01 = true, 0x02 = false. */
|
||||
|
||||
@@ -445,4 +445,85 @@ class AapSessionEngineTest : BaseTest() {
|
||||
engine.state.value.setting<AapSetting.AncMode>()!!.current shouldBe AapSetting.AncMode.Value.TRANSPARENCY
|
||||
}
|
||||
}
|
||||
|
||||
// ── HID descriptor handling ─────────────────────────────
|
||||
|
||||
@Nested
|
||||
inner class HidDescriptorTests {
|
||||
|
||||
private fun hidMessage(payload: ByteArray): AapMessage {
|
||||
val header = byteArrayOf(0x04, 0x00, (payload.size and 0xFF).toByte(), ((payload.size shr 8) and 0xFF).toByte())
|
||||
val cmdBytes = byteArrayOf(0x17, 0x00)
|
||||
val raw = header + cmdBytes + payload
|
||||
return AapMessage(raw = raw, commandType = 0x0017, payload = payload)
|
||||
}
|
||||
|
||||
private fun hexToBytes(hex: String): ByteArray =
|
||||
hex.split(" ").filter { it.isNotBlank() }.map { it.toInt(16).toByte() }.toByteArray()
|
||||
|
||||
@Test
|
||||
fun `0x0017 during HANDSHAKING triggers READY transition`() {
|
||||
val engine = createEngine()
|
||||
val scope = TestScope(UnconfinedTestDispatcher())
|
||||
|
||||
engine.start(scope)
|
||||
engine.onHandshakeSent()
|
||||
engine.state.value.connectionState shouldBe AapPodState.ConnectionState.HANDSHAKING
|
||||
|
||||
engine.processMessage(hidMessage(hexToBytes("00 04 00 00 01 00 FF")))
|
||||
|
||||
engine.state.value.connectionState shouldBe AapPodState.ConnectionState.READY
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `0x0017 refreshes lastMessageAt`() {
|
||||
val engine = createEngine()
|
||||
val scope = TestScope(UnconfinedTestDispatcher())
|
||||
engine.startReady(scope)
|
||||
|
||||
engine.state.value.lastMessageAt.shouldNotBeNull()
|
||||
val before = engine.state.value.lastMessageAt
|
||||
|
||||
every { timeSource.now() } returns Instant.ofEpochMilli(5000L)
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val descriptor = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
engine.processMessage(hidMessage(descriptor))
|
||||
|
||||
engine.state.value.lastMessageAt shouldBe Instant.ofEpochMilli(5000L)
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `malformed 0x0017 payload does not throw`() {
|
||||
val engine = createEngine()
|
||||
val scope = TestScope(UnconfinedTestDispatcher())
|
||||
engine.startReady(scope)
|
||||
|
||||
engine.processMessage(hidMessage(ByteArray(0)))
|
||||
engine.processMessage(hidMessage(hexToBytes("AB CD")))
|
||||
engine.processMessage(hidMessage(hexToBytes("00 04 00 00 44 00")))
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `0x0017 does not run through decode pipeline`() = runTest(UnconfinedTestDispatcher()) {
|
||||
val profile = mockProfile {
|
||||
every { decodeStemPress(any()) } returns StemPressEvent(StemPressEvent.PressType.SINGLE, StemPressEvent.Bud.LEFT)
|
||||
}
|
||||
val engine = createEngine(profile)
|
||||
engine.startReady(this as TestScope)
|
||||
|
||||
val collected = mutableListOf<StemPressEvent>()
|
||||
val collector = launch { engine.stemPressEvents.collect { collected.add(it) } }
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val descriptor = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
engine.processMessage(hidMessage(descriptor))
|
||||
runCurrent()
|
||||
|
||||
// If 0x0017 went through the decode pipeline, decodeStemPress would fire
|
||||
// and emit a StemPressEvent. The fast-path should bypass all decode calls.
|
||||
collected.shouldBeEmpty()
|
||||
collector.cancel()
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -0,0 +1,214 @@
|
||||
package eu.darken.capod.pods.core.apple.aap
|
||||
|
||||
import eu.darken.capod.pods.core.apple.aap.HidTracker.HidFrameType
|
||||
import io.kotest.matchers.collections.shouldBeEmpty
|
||||
import io.kotest.matchers.collections.shouldContainExactly
|
||||
import io.kotest.matchers.shouldBe
|
||||
import io.kotest.matchers.types.shouldBeInstanceOf
|
||||
import org.junit.jupiter.api.Nested
|
||||
import org.junit.jupiter.api.Test
|
||||
import testhelpers.BaseTest
|
||||
|
||||
class HidTrackerTest : BaseTest() {
|
||||
|
||||
private fun hexToBytes(hex: String): ByteArray =
|
||||
hex.split(" ").filter { it.isNotBlank() }.map { it.toInt(16).toByte() }.toByteArray()
|
||||
|
||||
// ── Classification ─────────────────────────────────────
|
||||
|
||||
@Nested
|
||||
inner class ClassifyTests {
|
||||
|
||||
@Test
|
||||
fun `service directory frame from Pro 3 capture`() {
|
||||
val payload = hexToBytes(
|
||||
"FE 00 00 06 41 50 00 00 00 80 00 00 41 4F 50 00 00 80 00 00 " +
|
||||
"52 54 50 00 00 80 00 00 42 54 4D 00 00 80 00 00 " +
|
||||
"44 53 50 31 00 80 00 00 44 53 50 32 00 80 00 00"
|
||||
)
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.ServiceDirectory>()
|
||||
result.services.shouldContainExactly("AP", "AOP", "RTP", "BTM", "DSP1", "DSP2")
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `descriptor bulk frame phase 0x81`() {
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val payload = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.Descriptor>()
|
||||
result.phase shouldBe 0x81
|
||||
result.fill shouldBe 0xFF
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `descriptor bulk frame phase 0x02`() {
|
||||
val fill = ByteArray(65) { 0xEF.toByte() }
|
||||
val payload = hexToBytes("00 04 00 00 44 00 01 C3 02") + fill
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.Descriptor>()
|
||||
result.phase shouldBe 0x02
|
||||
result.fill shouldBe 0xEF
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `terminator frame`() {
|
||||
val payload = hexToBytes("00 04 00 00 01 00 FF")
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.Terminator>()
|
||||
result.payloadSize shouldBe 7
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `short frame ending in FF but not 7 bytes is Other`() {
|
||||
val payload = hexToBytes("00 04 00 FF")
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.Other>()
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `empty payload is Other`() {
|
||||
val result = HidTracker.classify(ByteArray(0))
|
||||
result.shouldBeInstanceOf<HidFrameType.Other>()
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `random payload is Other`() {
|
||||
val payload = hexToBytes("AB CD EF 01 02 03 04 05 06 07 08")
|
||||
val result = HidTracker.classify(payload)
|
||||
result.shouldBeInstanceOf<HidFrameType.Other>()
|
||||
}
|
||||
}
|
||||
|
||||
// ── Batching ───────────────────────────────────────────
|
||||
|
||||
@Nested
|
||||
inner class BatchingTests {
|
||||
|
||||
@Test
|
||||
fun `same phase and fill batches together`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val payload = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
|
||||
tracker.consume(payload)
|
||||
tracker.consume(payload)
|
||||
tracker.consume(payload)
|
||||
logs.shouldBeEmpty()
|
||||
|
||||
tracker.flush()
|
||||
logs.size shouldBe 1
|
||||
logs[0] shouldBe "HID: 3 descriptor frames phase=0x81 fill=0xFF"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `phase change flushes previous batch`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fill81 = ByteArray(65) { 0xFF.toByte() }
|
||||
val payload81 = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill81
|
||||
|
||||
val fill02 = ByteArray(65) { 0xEF.toByte() }
|
||||
val payload02 = hexToBytes("00 04 00 00 44 00 01 C3 02") + fill02
|
||||
|
||||
tracker.consume(payload81)
|
||||
tracker.consume(payload81)
|
||||
tracker.consume(payload02)
|
||||
|
||||
logs.size shouldBe 1
|
||||
logs[0] shouldBe "HID: 2 descriptor frames phase=0x81 fill=0xFF"
|
||||
|
||||
tracker.flush()
|
||||
logs.size shouldBe 2
|
||||
logs[1] shouldBe "HID: 1 descriptor frames phase=0x02 fill=0xEF"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `same phase but different fill creates separate batch`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fillFF = ByteArray(65) { 0xFF.toByte() }
|
||||
val payloadFF = hexToBytes("00 04 00 00 44 00 01 A1 81") + fillFF
|
||||
|
||||
val fillEF = ByteArray(65) { 0xEF.toByte() }
|
||||
val payloadEF = hexToBytes("00 04 00 00 44 00 01 C3 81") + fillEF
|
||||
|
||||
tracker.consume(payloadFF)
|
||||
tracker.consume(payloadEF)
|
||||
|
||||
logs.size shouldBe 1
|
||||
logs[0] shouldBe "HID: 1 descriptor frames phase=0x81 fill=0xFF"
|
||||
|
||||
tracker.flush()
|
||||
logs.size shouldBe 2
|
||||
logs[1] shouldBe "HID: 1 descriptor frames phase=0x81 fill=0xEF"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `service directory flushes pending batch`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val descriptor = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
val directory = hexToBytes(
|
||||
"FE 00 00 02 41 50 00 00 00 80 00 00 41 4F 50 00 00 80 00 00"
|
||||
)
|
||||
|
||||
tracker.consume(descriptor)
|
||||
tracker.consume(descriptor)
|
||||
tracker.consume(directory)
|
||||
|
||||
logs.size shouldBe 2
|
||||
logs[0] shouldBe "HID: 2 descriptor frames phase=0x81 fill=0xFF"
|
||||
logs[1] shouldBe "HID: services=[AP, AOP] (20B)"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `terminator flushes pending batch`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val descriptor = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
val terminator = hexToBytes("00 04 00 00 01 00 FF")
|
||||
|
||||
tracker.consume(descriptor)
|
||||
tracker.consume(terminator)
|
||||
|
||||
logs.size shouldBe 2
|
||||
logs[0] shouldBe "HID: 1 descriptor frames phase=0x81 fill=0xFF"
|
||||
logs[1] shouldBe "HID: terminator (7B)"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `flush with zero count is no-op`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
tracker.flush()
|
||||
|
||||
logs.shouldBeEmpty()
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `reset clears pending batch without logging`() {
|
||||
val logs = mutableListOf<String>()
|
||||
val tracker = HidTracker { logs.add(it) }
|
||||
|
||||
val fill = ByteArray(65) { 0xFF.toByte() }
|
||||
val descriptor = hexToBytes("00 04 00 00 44 00 01 A1 81") + fill
|
||||
|
||||
tracker.consume(descriptor)
|
||||
tracker.consume(descriptor)
|
||||
tracker.reset()
|
||||
tracker.flush()
|
||||
|
||||
logs.shouldBeEmpty()
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user