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
This commit is contained in:
darken
2026-08-19 23:52:52 +02:00
parent 734e15c94d
commit b396ce457d
3 changed files with 330 additions and 60 deletions
@@ -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<AapSetting.AncMode>()?.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<AapSetting.AncMode>()?.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<AapSetting.AncMode>() ?: 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}"
),
)
}
@@ -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<out AapSetting>, 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),
)
}
}
@@ -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<TimeSource> {
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<KClass<out AapSetting>, 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<AapSetting.AncMode>()!!.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<KClass<out AapSetting>, 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<AapSetting.AncMode>()!!.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<KClass<out AapSetting>, 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<AapSetting.AncMode>()!!.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<KClass<out AapSetting>, 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<AapSetting.AncMode>()!!.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<AapSetting.AllowOffOption>().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<KClass<out AapSetting>, 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<AapSetting.AllowOffOption>()?.enabled shouldBe true
}
@Test
fun `unrelated setting report does not prematurely confirm a non-ANC command`() =
runTest(UnconfinedTestDispatcher()) {