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()) {