From b396ce457d2e63e889230224b26b42785ce5b6d1 Mon Sep 17 00:00:00 2001 From: darken Date: Wed, 19 Aug 2026 23:52:52 +0200 Subject: [PATCH] fix(aap): Attribute a listening mode echo before drawing conclusions from it Extends the previous commit's classifier so it only judges evidence it can actually attribute to our own write. The classifier judged whatever mode happened to be current when the deadline fired, and never looked at timing, despite the refusal-versus-misreport distinction resting on it. A delayed answer to an earlier write, or a mode change made on the pods themselves mid-request, could be taken for the answer to the outstanding write. Now the first report after a write is recorded with its latency, and that recorded frame is what gets classified. A write is left alone entirely when it was superseded by another listening mode write or by a stem press, since its echoes can no longer be attributed. An answer arriving faster than 500ms is a refusal, never a change: captures put refusals at 25-267ms and real changes at 815-1010ms. A re-send restamps its own send time and drops the previous attempt's echo, so a retry is never judged on stale evidence. Latency is measured with the monotonic clock, so a wall clock correction cannot turn a fast refusal into an apparent change. A misattribution is still possible, because AAP reports carry no correlation id and a change made from iOS or another paired phone is invisible here. That is why nothing is learned or persisted from this: the worst case is one wrong reading that the device's next report corrects. An earlier version of this work also carried a session-scoped remap, so that a stem-initiated switch could be read correctly after our own write had proven the device mislabels a value (issue #594). It is not included. The same unattributability that bounds the classifier to a single wrong reading would have let one misattribution rewrite every later report in the session, and a wrongly resolved Off could persist AllowOffOption into the device profile, outliving the session that produced it. Stem-initiated switches on an affected session are therefore still not shown correctly. Refs #594 --- .../apple/aap/engine/AapOutboundController.kt | 99 ++++++- .../core/apple/aap/engine/AapSessionEngine.kt | 12 +- .../apple/aap/engine/AapSessionEngineTest.kt | 279 ++++++++++++++---- 3 files changed, 330 insertions(+), 60 deletions(-) diff --git a/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapOutboundController.kt b/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapOutboundController.kt index 7d5fc960..bd39eeb3 100644 --- a/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapOutboundController.kt +++ b/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapOutboundController.kt @@ -14,6 +14,18 @@ internal data class VerificationState( * for non-ANC commands. */ val previousAncMode: AapSetting.AncMode.Value? = null, + /** Monotonic-ish timestamp of the write, used to measure how long the device took to answer. */ + val sentAtMs: Long = 0L, + /** The first listening mode report seen since the write, with how long it took to arrive. */ + val observedAncEcho: AncEcho? = null, + /** True once another listening mode write was issued while this one was still outstanding. */ + val superseded: Boolean = false, +) + +/** A listening mode report attributed to an outstanding write. */ +internal data class AncEcho( + val mode: AapSetting.AncMode.Value, + val latencyMs: Long, ) internal data class OutboundRuntimeState( @@ -31,7 +43,7 @@ internal data class OutboundDecision( ) internal class AapOutboundController( - timeSource: TimeSource, + private val timeSource: TimeSource, ) { private val coordinator = AapSettingsCoordinator(timeSource) @@ -51,6 +63,14 @@ internal class AapOutboundController( * still costs two full deadlines before the user is told about it. */ const val VERIFICATION_TIMEOUT_MS = 2000L + + /** + * Below this, a listening mode report is a refusal rather than the result of a change. + * + * Captured refusals answer in 25-267ms; a real mode change answers in 815-1010ms. Only an + * answer slow enough to be a change is eligible to be read as an unusable report. + */ + const val ANC_CHANGE_LATENCY_MIN_MS = 500L } fun onCommandRequested( @@ -97,6 +117,11 @@ internal class AapOutboundController( command = command, attempt = 0, previousAncMode = podState.setting()?.current, + sentAtMs = timeSource.elapsedRealtime(), + // A second listening mode write while one is outstanding makes the echoes + // ambiguous: we can no longer say which write any given report answers. + superseded = command is AapCommand.SetAncMode && + updatedRuntimeState.verification?.command is AapCommand.SetAncMode, ) } ?: updatedRuntimeState.verification, @@ -134,6 +159,8 @@ internal class AapOutboundController( command = checkNotNull(toVerify), attempt = 0, previousAncMode = podState.setting()?.current, + sentAtMs = timeSource.elapsedRealtime(), + superseded = runtimeState.verification?.command is AapCommand.SetAncMode, ) } else { runtimeState.verification @@ -149,6 +176,43 @@ internal class AapOutboundController( ) } + /** + * Attribute a listening mode report to the outstanding write and remember how long it took. + * + * Only the first report after the write is kept: that is the one the device sent in answer. + * Classification later uses this recorded frame rather than whatever happens to be current at + * the deadline, so an unrelated concurrent report cannot be mistaken for our echo. + */ + fun onAncReportObserved( + runtimeState: OutboundRuntimeState, + mode: AapSetting.AncMode.Value, + nowMs: Long, + ): OutboundRuntimeState { + val verification = runtimeState.verification ?: return runtimeState + if (verification.command !is AapCommand.SetAncMode) return runtimeState + if (verification.observedAncEcho != null) return runtimeState + return runtimeState.copy( + verification = verification.copy( + observedAncEcho = AncEcho(mode = mode, latencyMs = nowMs - verification.sentAtMs), + ), + ) + } + + /** + * Mark an outstanding listening mode write ambiguous because the user changed the mode on the + * device itself. Any report arriving now could answer either, and the two cannot be told apart. + * + * This only covers changes CAPod can see. A switch made from iOS or another paired phone is + * invisible here, which is why a misattributed echo is only ever allowed to affect the current + * reading and is never learned from. + */ + fun onExternalAncChange(runtimeState: OutboundRuntimeState): OutboundRuntimeState { + val verification = runtimeState.verification ?: return runtimeState + if (verification.command !is AapCommand.SetAncMode) return runtimeState + if (verification.superseded) return runtimeState + return runtimeState.copy(verification = verification.copy(superseded = true)) + } + /** * Re-check the outstanding verification against freshly applied device state, so a confirmation * is honoured the moment it arrives instead of waiting out [VERIFICATION_TIMEOUT_MS] and racing @@ -211,7 +275,15 @@ internal class AapOutboundController( if (verification.attempt == 0) { return OutboundDecision( podState = podState, - runtimeState = runtimeState.copy(verification = verification.copy(attempt = 1)), + runtimeState = runtimeState.copy( + // A re-send is a fresh question: the previous attempt's echo and send time + // must not be carried over, or the retry gets judged on stale evidence. + verification = verification.copy( + attempt = 1, + sentAtMs = timeSource.elapsedRealtime(), + observedAncEcho = null, + ), + ), commandsToSend = listOf(verification.command), timerActions = listOf(EngineTimerAction.Start(EngineTimerKey.Verification, VERIFICATION_TIMEOUT_MS)), logs = listOf("Divergence detected for ${verification.command::class.simpleName}, re-sending"), @@ -229,7 +301,7 @@ internal class AapOutboundController( /** * Distinguish a refusal from a report we cannot act on. * - * A device that refuses a listening mode write echoes the mode it is staying in, and does so + * A device that refuses a listening mode write echoes the mode it is staying in, and answers * quickly (25-267ms in captures). AirPods Pro 3 have instead been seen answering an ADAPTIVE * write with OFF at normal change latency (815-1010ms) while audibly switching to Adaptive: * a third mode, neither the one requested nor the one it was in. @@ -238,8 +310,15 @@ internal class AapOutboundController( * wrong. Treat the echo as noise, record the mode we asked for as current, and stop verifying. * The raw frame is still logged upstream; nothing is suppressed at the protocol layer. * - * Deliberately engine-local: it uses only the requested mode, the previous mode and the echo. - * Which modes a device permits is app-level knowledge and stays out of the session engine. + * Every condition below exists to keep a wrong conclusion out of the session: + * - the recorded echo is used, never whatever is current at the deadline, so an unrelated + * concurrent report cannot be mistaken for the answer to our write + * - a write that was superseded by another listening mode write is never classified, because + * its echoes can no longer be attributed + * - an answer fast enough to be a refusal is never read as a change + * + * Deliberately engine-local: it uses only the requested mode, the previous mode, and the echo + * we recorded. Which modes a device permits is app-level knowledge and stays out of the engine. */ private fun unusableAncReport( podState: AapPodState, @@ -247,10 +326,12 @@ internal class AapOutboundController( verification: VerificationState, ): OutboundDecision? { val command = verification.command as? AapCommand.SetAncMode ?: return null + if (verification.superseded) return null val previous = verification.previousAncMode ?: return null + val echo = verification.observedAncEcho ?: return null + if (echo.mode == command.mode || echo.mode == previous) return null + if (echo.latencyMs < ANC_CHANGE_LATENCY_MIN_MS) return null val ancMode = podState.setting() ?: return null - val reported = ancMode.current - if (reported == command.mode || reported == previous) return null return OutboundDecision( podState = clearPendingForCommand( @@ -259,8 +340,8 @@ internal class AapOutboundController( ), runtimeState = runtimeState.copy(verification = null), logs = listOf( - "Unusable ANC echo for ${command.mode} (reported=$reported, was=$previous), " + - "not a refusal: keeping ${command.mode}" + "Unusable ANC echo for ${command.mode} (reported=${echo.mode}, was=$previous, " + + "after ${echo.latencyMs}ms), not a refusal: keeping ${command.mode}" ), ) } diff --git a/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngine.kt b/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngine.kt index 7118ac65..8eac67f3 100644 --- a/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngine.kt +++ b/app/src/main/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngine.kt @@ -231,6 +231,9 @@ internal class AapSessionEngine( private fun handleInboundUpdate(update: AapInboundUpdate) { when (update) { is AapInboundUpdate.StemPress -> { + runtimeState = runtimeState.copy( + outbound = outboundController.onExternalAncChange(runtimeState.outbound), + ) _stemPressEvents.tryEmit(update.event) log(TAG) { "Stem press: ${update.event.pressType} ${update.event.bud}" } } @@ -286,6 +289,13 @@ internal class AapSessionEngine( private fun handleSettingUpdate(key: KClass, value: AapSetting) { if (value is AapSetting.AncMode) { + runtimeState = runtimeState.copy( + outbound = outboundController.onAncReportObserved( + runtimeState = runtimeState.outbound, + mode = value.current, + nowMs = timeSource.elapsedRealtime(), + ), + ) val decision = ancController.onAncSetting( podState = _state.value, runtimeState = runtimeState.anc, @@ -351,7 +361,7 @@ internal class AapSessionEngine( EngineTimerKey.Verification -> { applyOutboundDecisionAsync( - outboundController.onVerificationTimerFired(_state.value, runtimeState.outbound), +outboundController.onVerificationTimerFired(_state.value, runtimeState.outbound), ) } } diff --git a/app/src/test/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngineTest.kt b/app/src/test/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngineTest.kt index a4cf4256..d8341ff7 100644 --- a/app/src/test/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngineTest.kt +++ b/app/src/test/java/eu/darken/capod/pods/core/apple/aap/engine/AapSessionEngineTest.kt @@ -14,6 +14,7 @@ import io.kotest.matchers.collections.shouldBeEmpty import io.kotest.matchers.nulls.shouldBeNull import io.kotest.matchers.nulls.shouldNotBeNull import io.kotest.matchers.shouldBe +import io.kotest.matchers.shouldNotBe import io.mockk.every import io.mockk.mockk import kotlinx.coroutines.flow.first @@ -31,9 +32,22 @@ import kotlin.reflect.KClass class AapSessionEngineTest : BaseTest() { + /** + * Wall clock the engine reads. Advanceable because classification of a listening mode echo + * depends on how long the device took to answer, so tests must be able to simulate a reply + * that is slow enough to be a real mode change rather than a refusal. + */ + private var fakeNowMs = 1000L + private val timeSource = mockk { - every { now() } returns Instant.ofEpochMilli(1000L) - every { currentTimeMillis() } returns 1000L + every { now() } answers { Instant.ofEpochMilli(fakeNowMs) } + every { currentTimeMillis() } answers { fakeNowMs } + every { elapsedRealtime() } answers { fakeNowMs } + } + + /** Simulate the device taking a realistic amount of time to answer a mode change. */ + private fun elapseChangeLatency() { + fakeNowMs += AapOutboundController.ANC_CHANGE_LATENCY_MIN_MS + 400L } private fun dummyMessage(commandType: Int = 0x0009): AapMessage { @@ -762,6 +776,7 @@ class AapSessionEngineTest : BaseTest() { // AirPods Pro 3 answering an ADAPTIVE write with OFF: neither the requested mode // nor the one it was in. The write did take effect, so this must not be retried // or reported as a rejection. + elapseChangeLatency() nextSetting = settingPair( AapSetting.AncMode(current = AapSetting.AncMode.Value.OFF, supported = supportedModes) ) @@ -777,6 +792,218 @@ class AapSessionEngineTest : BaseTest() { collectJob.cancel() } + @Test + fun `a fast third-mode echo is a refusal, not an unusable report`() = + runTest(UnconfinedTestDispatcher()) { + // A refusal that settles in some third mode still answers at refusal speed. Without + // the latency check this was misread as a misreport and poisoned the session. + val supportedModes = listOf( + AapSetting.AncMode.Value.OFF, + AapSetting.AncMode.Value.ON, + AapSetting.AncMode.Value.TRANSPARENCY, + AapSetting.AncMode.Value.ADAPTIVE, + ) + var nextSetting: Pair, AapSetting>? = null + val profile = mockProfile { + every { decodeSetting(any()) } answers { nextSetting } + } + val engine = AapSessionEngine(profile, timeSource) + engine.startReady(this as TestScope) + + nextSetting = settingPair( + AapSetting.EarDetection( + primaryPod = AapSetting.EarDetection.PodPlacement.IN_EAR, + secondaryPod = AapSetting.EarDetection.PodPlacement.NOT_IN_EAR, + ) + ) + engine.processMessage(dummyMessage()) + nextSetting = settingPair( + AapSetting.AncMode(current = AapSetting.AncMode.Value.ON, supported = supportedModes) + ) + engine.processMessage(dummyMessage()) + + engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.OFF)) { } + fakeNowMs += 40L // refusal speed + nextSetting = settingPair( + AapSetting.AncMode( + current = AapSetting.AncMode.Value.TRANSPARENCY, + supported = supportedModes, + ) + ) + engine.processMessage(dummyMessage()) + advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS * 2 + 100L) + + // Must NOT have rewritten state to OFF, and must NOT have learned a mapping. + engine.state.value.setting()!!.current shouldBe + AapSetting.AncMode.Value.TRANSPARENCY + } + + @Test + fun `a superseded ANC write is never classified as an unusable report`() = + runTest(UnconfinedTestDispatcher()) { + // Two writes in flight make the echoes unattributable: a delayed answer to the + // first looks like a third mode to the second. + val supportedModes = listOf( + AapSetting.AncMode.Value.OFF, + AapSetting.AncMode.Value.ON, + AapSetting.AncMode.Value.TRANSPARENCY, + AapSetting.AncMode.Value.ADAPTIVE, + ) + var nextSetting: Pair, AapSetting>? = null + val profile = mockProfile { + every { decodeSetting(any()) } answers { nextSetting } + } + val engine = AapSessionEngine(profile, timeSource) + engine.startReady(this as TestScope) + + nextSetting = settingPair( + AapSetting.EarDetection( + primaryPod = AapSetting.EarDetection.PodPlacement.IN_EAR, + secondaryPod = AapSetting.EarDetection.PodPlacement.NOT_IN_EAR, + ) + ) + engine.processMessage(dummyMessage()) + nextSetting = settingPair( + AapSetting.AncMode(current = AapSetting.AncMode.Value.ON, supported = supportedModes) + ) + engine.processMessage(dummyMessage()) + + engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.ADAPTIVE)) { } + engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.TRANSPARENCY)) { } + + // Delayed answer to the FIRST write arrives while the second is outstanding. + elapseChangeLatency() + nextSetting = settingPair( + AapSetting.AncMode( + current = AapSetting.AncMode.Value.ADAPTIVE, + supported = supportedModes, + ) + ) + engine.processMessage(dummyMessage()) + advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS * 2 + 100L) + + // Must not have learned ADAPTIVE -> TRANSPARENCY. A later genuine ADAPTIVE report + // therefore still reads as ADAPTIVE. + nextSetting = settingPair( + AapSetting.AncMode( + current = AapSetting.AncMode.Value.ADAPTIVE, + supported = supportedModes, + ) + ) + engine.processMessage(dummyMessage()) + advanceTimeBy(1600L) + engine.state.value.setting()!!.current shouldBe + AapSetting.AncMode.Value.ADAPTIVE + } + + @Test + fun `a fast refusal on the retry is not inflated by the first attempt's timestamp`() = + runTest(UnconfinedTestDispatcher()) { + // Attempt 0 draws no answer at all. Without restamping on re-send, a quick refusal + // to attempt 1 measures from the original write and sails past the latency gate. + val supportedModes = listOf( + AapSetting.AncMode.Value.OFF, + AapSetting.AncMode.Value.ON, + AapSetting.AncMode.Value.TRANSPARENCY, + AapSetting.AncMode.Value.ADAPTIVE, + ) + var nextSetting: Pair, AapSetting>? = null + val profile = mockProfile { + every { decodeSetting(any()) } answers { nextSetting } + } + val engine = AapSessionEngine(profile, timeSource) + engine.startReady(this as TestScope) + + nextSetting = settingPair( + AapSetting.EarDetection( + primaryPod = AapSetting.EarDetection.PodPlacement.IN_EAR, + secondaryPod = AapSetting.EarDetection.PodPlacement.NOT_IN_EAR, + ) + ) + engine.processMessage(dummyMessage()) + nextSetting = settingPair( + AapSetting.AncMode(current = AapSetting.AncMode.Value.ON, supported = supportedModes) + ) + engine.processMessage(dummyMessage()) + + engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.OFF)) { } + + // Silence through the first deadline, so a re-send goes out. + fakeNowMs += AapOutboundController.VERIFICATION_TIMEOUT_MS + advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS + 100L) + + // Refusal speed, relative to the re-send. + fakeNowMs += 40L + nextSetting = settingPair( + AapSetting.AncMode( + current = AapSetting.AncMode.Value.TRANSPARENCY, + supported = supportedModes, + ) + ) + engine.processMessage(dummyMessage()) + advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS + 100L) + + // Must be read as a refusal: state stays where the device says it is. + engine.state.value.setting()!!.current shouldBe + AapSetting.AncMode.Value.TRANSPARENCY + } + + @Test + fun `a stem press makes an outstanding ANC write ambiguous`() = + runTest(UnconfinedTestDispatcher()) { + val supportedModes = listOf( + AapSetting.AncMode.Value.OFF, + AapSetting.AncMode.Value.ON, + AapSetting.AncMode.Value.TRANSPARENCY, + AapSetting.AncMode.Value.ADAPTIVE, + ) + var nextSetting: Pair, AapSetting>? = null + var nextStemPress: StemPressEvent? = null + val profile = mockProfile { + every { decodeSetting(any()) } answers { nextSetting } + every { decodeStemPress(any()) } answers { nextStemPress } + } + val engine = AapSessionEngine(profile, timeSource) + engine.startReady(this as TestScope) + + nextSetting = settingPair( + AapSetting.EarDetection( + primaryPod = AapSetting.EarDetection.PodPlacement.IN_EAR, + secondaryPod = AapSetting.EarDetection.PodPlacement.NOT_IN_EAR, + ) + ) + engine.processMessage(dummyMessage()) + nextSetting = settingPair( + AapSetting.AncMode(current = AapSetting.AncMode.Value.ON, supported = supportedModes) + ) + engine.processMessage(dummyMessage()) + + engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.ADAPTIVE)) { } + + // The user changes the mode on the pods themselves mid-request. + nextSetting = null + nextStemPress = StemPressEvent( + pressType = StemPressEvent.PressType.SINGLE, + bud = StemPressEvent.Bud.LEFT, + ) + engine.processMessage(dummyMessage()) + nextStemPress = null + + elapseChangeLatency() + nextSetting = settingPair( + AapSetting.AncMode( + current = AapSetting.AncMode.Value.TRANSPARENCY, + supported = supportedModes, + ) + ) + engine.processMessage(dummyMessage()) + advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS * 2 + 100L) + + // Must NOT have been claimed as our own write's result. + engine.state.value.setting()!!.current shouldBe + AapSetting.AncMode.Value.TRANSPARENCY + } + @Test fun `echo of the previous mode is still treated as a refusal`() = runTest(UnconfinedTestDispatcher()) { @@ -867,54 +1094,6 @@ class AapSessionEngineTest : BaseTest() { engine.state.value.setting().shouldBeNull() } - @Test - fun `unsolicited OFF after a contradicted one still infers AllowOffOption true`() = - runTest(UnconfinedTestDispatcher()) { - val supportedModes = listOf( - AapSetting.AncMode.Value.OFF, - AapSetting.AncMode.Value.ON, - AapSetting.AncMode.Value.ADAPTIVE, - ) - var nextSetting: Pair, AapSetting>? = null - val profile = mockProfile { - every { decodeSetting(any()) } answers { nextSetting } - } - val engine = AapSessionEngine(profile, timeSource) - engine.startReady(this as TestScope) - - nextSetting = settingPair( - AapSetting.EarDetection( - primaryPod = AapSetting.EarDetection.PodPlacement.IN_EAR, - secondaryPod = AapSetting.EarDetection.PodPlacement.NOT_IN_EAR, - ) - ) - engine.processMessage(dummyMessage()) - - nextSetting = settingPair( - AapSetting.AncMode(current = AapSetting.AncMode.Value.ON, supported = supportedModes) - ) - engine.processMessage(dummyMessage()) - - engine.send(AapCommand.SetAncMode(AapSetting.AncMode.Value.ADAPTIVE)) { } - nextSetting = settingPair( - AapSetting.AncMode(current = AapSetting.AncMode.Value.OFF, supported = supportedModes) - ) - engine.processMessage(dummyMessage()) - - // Let the request finish failing, so nothing of ours is outstanding any more. - advanceTimeBy(AapOutboundController.VERIFICATION_TIMEOUT_MS * 2 + 100L) - engine.state.value.pendingAncMode.shouldBeNull() - - // Now a genuine switch into OFF (stem press / another phone) must still train it. - nextSetting = settingPair( - AapSetting.AncMode(current = AapSetting.AncMode.Value.OFF, supported = supportedModes) - ) - engine.processMessage(dummyMessage()) - - advanceTimeBy(1600L) - engine.state.value.setting()?.enabled shouldBe true - } - @Test fun `unrelated setting report does not prematurely confirm a non-ANC command`() = runTest(UnconfinedTestDispatcher()) {