feat(device): Log the effective BLE scan configuration

A capture that shows no scan results cannot currently answer whether the scan was filtered. The configuration is decided once when the scan starts, which is usually long before the recording that is meant to diagnose it, so the line is re-emitted when a recording begins while the scan is already running. The re-emission drops against the value captured at the first emission instead of drop(1): launchIn subscribes asynchronously, so a StateFlow replays whatever is current at subscription time. A recording started in that gap would be swallowed as if it were the initial value, which is exactly the case the line exists for. filterPolicy is a parameter rather than something derived from the filter set, because the unfiltered mode is implemented as a single match-all filter. A count-based summary would report it as a filtered scan, inverting the answer. "Requested" and not "filtering"/"batching": adapter capability plus our own setting is what we asked the platform for, not proof that the controller offloaded anything.
2026-09-14 18:26:11 -04:00 · 2026-09-01 10:11:01 +02:00
parent 2ba90e1d18
commit 39a6c3c89f
5 changed files with 270 additions and 14 deletions
@@ -10,7 +10,9 @@ import android.content.Context
 import android.content.Intent
 import dagger.hilt.android.qualifiers.ApplicationContext
 import eu.darken.capod.common.TimeSource
+import eu.darken.capod.common.debug.Bugs
 import eu.darken.capod.common.debug.logging.Logging.Priority.DEBUG
+import eu.darken.capod.common.debug.logging.Logging.Priority.INFO
 import eu.darken.capod.common.debug.logging.Logging.Priority.VERBOSE
 import eu.darken.capod.common.debug.logging.Logging.Priority.WARN
 import eu.darken.capod.common.debug.logging.log
@@ -21,6 +23,8 @@ import kotlinx.coroutines.channels.awaitClose
 import kotlinx.coroutines.delay
 import kotlinx.coroutines.flow.Flow
 import kotlinx.coroutines.flow.callbackFlow
+import kotlinx.coroutines.flow.dropWhile
+import kotlinx.coroutines.flow.filter
 import kotlinx.coroutines.flow.launchIn
 import kotlinx.coroutines.flow.map
 import kotlinx.coroutines.flow.onEach
@@ -39,6 +43,7 @@ class BleScanner @Inject constructor(

    @SuppressLint("MissingPermission") fun scan(
        filters: Set<ScanFilter>,
+        filterPolicy: ScanFilterPolicy,
        scannerMode: ScannerMode = ScannerMode.BALANCED,
        disableOffloadFiltering: Boolean = false,
        disableOffloadBatching: Boolean = false,
@@ -50,14 +55,16 @@ class BleScanner @Inject constructor(

        val adapter = bluetoothManager.adapter ?: throw IllegalStateException("Bluetooth adapter unavailable")

-        val useOffloadedFiltering = adapter.isOffloadedFilteringSupported.also {
+        val offloadFilteringSupported = adapter.isOffloadedFilteringSupported.also {
            log(TAG, if (it) DEBUG else WARN) { "isOffloadedFilteringSupported=$it" }
-        } && !disableOffloadFiltering
+        }
+        val useOffloadedFiltering = offloadFilteringSupported && !disableOffloadFiltering
        if (disableOffloadFiltering) log(TAG, WARN) { "Offloaded filtering is disabled!" }

-        val useOffloadedBatching = adapter.isOffloadedScanBatchingSupported.also {
+        val offloadBatchingSupported = adapter.isOffloadedScanBatchingSupported.also {
            log(TAG, if (it) DEBUG else WARN) { "isOffloadedScanBatchingSupported=$it" }
-        } && !disableOffloadBatching
+        }
+        val useOffloadedBatching = offloadBatchingSupported && !disableOffloadBatching
        if (disableOffloadBatching) log(TAG, WARN) { "Offloaded scan-batching is disabled!" }

        if (disableDirectScanCallback) log(TAG, WARN) { "Direct scan callback is disabled!" }
@@ -128,6 +135,16 @@ class BleScanner @Inject constructor(
            else -> emptyList()
        }

+        val reportDelayMs = if (useOffloadedBatching) {
+            when (scannerMode) {
+                ScannerMode.LOW_POWER -> 2000L
+                ScannerMode.BALANCED -> 1000L
+                ScannerMode.LOW_LATENCY -> 500L
+            }
+        } else {
+            0L // Anything > 0 enables batching
+        }
+
        val scanSettings = ScanSettings.Builder().apply {
            setCallbackType(ScanSettings.CALLBACK_TYPE_ALL_MATCHES)
            when (scannerMode) {
@@ -148,18 +165,35 @@ class BleScanner @Inject constructor(
                }
            }

-            val delay = if (useOffloadedBatching) {
-                when (scannerMode) {
-                    ScannerMode.LOW_POWER -> 2000L
-                    ScannerMode.BALANCED -> 1000L
-                    ScannerMode.LOW_LATENCY -> 500L
-                }
-            } else {
-                0L // Anything > 0 enables batching
-            }
-            setReportDelay(delay)
+            setReportDelay(reportDelayMs)
        }.build()

+        val config = ScanConfig(
+            scannerMode = scannerMode,
+            filterPolicy = filterPolicy,
+            platformFilterCount = filterList.size,
+            requestedFilterCount = filters.size,
+            offloadFilteringSupported = offloadFilteringSupported,
+            offloadFilteringDisabledBySetting = disableOffloadFiltering,
+            offloadBatchingSupported = offloadBatchingSupported,
+            offloadBatchingDisabledBySetting = disableOffloadBatching,
+            reportDelayMs = reportDelayMs,
+            directCallback = !disableDirectScanCallback,
+        )
+        log(TAG, INFO) { config.summary() }
+
+        // A recording usually starts while a scan is already running, i.e. after the line above went
+        // nowhere. Re-emit so the capture contains the configuration it is meant to diagnose.
+        val debugAtStart = Bugs.isDebug.value
+        Bugs.isDebug
+            // Not drop(1): launchIn subscribes asynchronously, so the replayed value is whatever is
+            // current at subscription time. A recording started in that gap would be discarded as
+            // though it were the initial value.
+            .dropWhile { it == debugAtStart }
+            .filter { it }
+            .onEach { log(TAG, INFO) { "${config.summary()} (recording started)" } }
+            .launchIn(this)
+
        try {
            if (disableDirectScanCallback) {
                val callbackIntent = createStartIntent()
@@ -239,3 +273,30 @@ class BleScanner @Inject constructor(
        private val TAG = logTag("Bluetooth", "BleScanner")
    }
 }
+
+internal data class ScanConfig(
+    val scannerMode: ScannerMode,
+    val filterPolicy: ScanFilterPolicy,
+    val platformFilterCount: Int,
+    val requestedFilterCount: Int,
+    val offloadFilteringSupported: Boolean,
+    val offloadFilteringDisabledBySetting: Boolean,
+    val offloadBatchingSupported: Boolean,
+    val offloadBatchingDisabledBySetting: Boolean,
+    val reportDelayMs: Long,
+    val directCallback: Boolean,
+) {
+    // "Requested" rather than "filtering"/"batching": adapter capability plus our own setting is
+    // what we asked the platform for, not proof that the controller offloaded anything.
+    fun summary(): String {
+        val offloadFilteringRequested = offloadFilteringSupported && !offloadFilteringDisabledBySetting
+        val offloadBatchingRequested = offloadBatchingSupported && !offloadBatchingDisabledBySetting
+        return "Scan config: mode=$scannerMode, filterPolicy=$filterPolicy, " +
+            "platformFilters=$platformFilterCount/$requestedFilterCount, " +
+            "offloadFilteringRequested=$offloadFilteringRequested " +
+            "(supported=$offloadFilteringSupported, disabledBySetting=$offloadFilteringDisabledBySetting), " +
+            "offloadBatchingRequested=$offloadBatchingRequested " +
+            "(supported=$offloadBatchingSupported, disabledBySetting=$offloadBatchingDisabledBySetting), " +
+            "reportDelay=${reportDelayMs}ms, callback=${if (directCallback) "direct" else "intent"}"
+    }
+}
@@ -0,0 +1,3 @@
+package eu.darken.capod.common.bluetooth
+
+enum class ScanFilterPolicy { PROXIMITY_PAIRING, MATCH_ALL }
@@ -5,6 +5,7 @@ import eu.darken.capod.common.TimeSource
 import eu.darken.capod.common.bluetooth.BleScanResult
 import eu.darken.capod.common.bluetooth.BleScanner
 import eu.darken.capod.common.bluetooth.BluetoothManager2
+import eu.darken.capod.common.bluetooth.ScanFilterPolicy
 import eu.darken.capod.common.bluetooth.ScannerMode
 import eu.darken.capod.common.bluetooth.onlyNewAndUnique
 import eu.darken.capod.common.coroutine.AppScope
@@ -215,6 +216,10 @@ class BlePodMonitor @Inject constructor(
                emitAll(
                    bleScanner.scan(
                        filters = filters,
+                        filterPolicy = when {
+                            options.showUnfiltered -> ScanFilterPolicy.MATCH_ALL
+                            else -> ScanFilterPolicy.PROXIMITY_PAIRING
+                        },
                        scannerMode = options.scannerMode,
                        disableOffloadFiltering = options.offloadedFilteringDisabled,
                        disableOffloadBatching = options.offloadedBatchingDisabled,
@@ -0,0 +1,184 @@
+package eu.darken.capod.common.bluetooth
+
+import android.bluetooth.BluetoothAdapter
+import android.bluetooth.le.BluetoothLeScanner
+import androidx.test.core.app.ApplicationProvider
+import eu.darken.capod.common.debug.Bugs
+import eu.darken.capod.common.debug.logging.Logging
+import io.kotest.matchers.collections.shouldHaveSize
+import io.kotest.matchers.shouldBe
+import io.kotest.matchers.string.shouldContain
+import io.mockk.every
+import io.mockk.mockk
+import kotlinx.coroutines.flow.launchIn
+import kotlinx.coroutines.test.runCurrent
+import kotlinx.coroutines.test.runTest
+import org.junit.After
+import org.junit.Before
+import org.junit.Test
+import org.junit.runner.RunWith
+import org.robolectric.RobolectricTestRunner
+import org.robolectric.annotation.Config
+import testhelpers.BaseTest
+import testhelpers.TestApplication
+import testhelpers.TestTimeSource
+import java.util.concurrent.CopyOnWriteArrayList
+
+/**
+ * A capture that shows no BLE results has to answer whether the scan was filtered at all. The
+ * configuration is decided once when the scan starts, which is usually before the recording the
+ * investigator is reading.
+ */
+@RunWith(RobolectricTestRunner::class)
+@Config(application = TestApplication::class)
+class BleScannerConfigLogTest : BaseTest() {
+
+    private val logLines = CopyOnWriteArrayList<String>()
+    private val logCapture = object : Logging.Logger {
+        override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map<String, Any>?) {
+            logLines.add(message)
+        }
+    }
+
+    @Before
+    fun setup() {
+        Bugs.isDebug.value = false
+        Logging.install(logCapture)
+    }
+
+    @After
+    fun teardown() {
+        Logging.remove(logCapture)
+        Bugs.isDebug.value = false
+    }
+
+    private fun configLines() = logLines.filter { it.startsWith("Scan config:") }
+
+    private fun createScanner(
+        offloadFilteringSupported: Boolean = true,
+        offloadBatchingSupported: Boolean = true,
+    ): BleScanner {
+        val adapter = mockk<BluetoothAdapter>(relaxed = true).apply {
+            every { isOffloadedFilteringSupported } returns offloadFilteringSupported
+            every { isOffloadedScanBatchingSupported } returns offloadBatchingSupported
+        }
+        val leScanner = mockk<BluetoothLeScanner>(relaxed = true)
+        val bluetoothManager = mockk<BluetoothManager2>().apply {
+            every { this@apply.adapter } returns adapter
+            every { scanner } returns leScanner
+        }
+        return BleScanner(
+            context = ApplicationProvider.getApplicationContext(),
+            bluetoothManager = bluetoothManager,
+            scanResultForwarder = BleScanResultForwarder(),
+            timeSource = TestTimeSource(),
+        )
+    }
+
+    private fun createConfig(
+        filterPolicy: ScanFilterPolicy = ScanFilterPolicy.PROXIMITY_PAIRING,
+        platformFilterCount: Int = 1,
+        requestedFilterCount: Int = 1,
+        offloadFilteringSupported: Boolean = true,
+        offloadFilteringDisabledBySetting: Boolean = false,
+        offloadBatchingSupported: Boolean = true,
+        offloadBatchingDisabledBySetting: Boolean = false,
+    ) = ScanConfig(
+        scannerMode = ScannerMode.BALANCED,
+        filterPolicy = filterPolicy,
+        platformFilterCount = platformFilterCount,
+        requestedFilterCount = requestedFilterCount,
+        offloadFilteringSupported = offloadFilteringSupported,
+        offloadFilteringDisabledBySetting = offloadFilteringDisabledBySetting,
+        offloadBatchingSupported = offloadBatchingSupported,
+        offloadBatchingDisabledBySetting = offloadBatchingDisabledBySetting,
+        reportDelayMs = 1000L,
+        directCallback = true,
+    )
+
+    /**
+     * Both render `offloadFilteringRequested=false`, and the reader has to be able to tell a device
+     * that cannot offload from a user who turned offloading off.
+     */
+    @Test
+    fun `an unsupported adapter reads differently from a disabled setting`() {
+        val unsupported = createConfig(
+            offloadFilteringSupported = false,
+            offloadBatchingSupported = false,
+        ).summary()
+        unsupported shouldContain "offloadFilteringRequested=false (supported=false, disabledBySetting=false)"
+        unsupported shouldContain "offloadBatchingRequested=false (supported=false, disabledBySetting=false)"
+
+        val disabled = createConfig(
+            offloadFilteringDisabledBySetting = true,
+            offloadBatchingDisabledBySetting = true,
+        ).summary()
+        disabled shouldContain "offloadFilteringRequested=false (supported=true, disabledBySetting=true)"
+        disabled shouldContain "offloadBatchingRequested=false (supported=true, disabledBySetting=true)"
+    }
+
+    @Test
+    fun `the filters that reached the platform are reported against the requested ones`() {
+        createConfig(
+            platformFilterCount = 0,
+            requestedFilterCount = 1,
+            offloadFilteringDisabledBySetting = true,
+        ).summary() shouldContain "platformFilters=0/1"
+
+        createConfig(platformFilterCount = 1, requestedFilterCount = 1).summary() shouldContain "platformFilters=1/1"
+    }
+
+    /**
+     * The unfiltered scan mode is implemented as a single match-all filter, so the filter count
+     * alone reports it as a filtered scan. Only the policy separates the two.
+     */
+    @Test
+    fun `a match-all scan is distinguishable from a filtered one at the same filter count`() {
+        createConfig(filterPolicy = ScanFilterPolicy.MATCH_ALL).summary() shouldContain
+            "filterPolicy=MATCH_ALL, platformFilters=1/1"
+
+        createConfig(filterPolicy = ScanFilterPolicy.PROXIMITY_PAIRING).summary() shouldContain
+            "filterPolicy=PROXIMITY_PAIRING, platformFilters=1/1"
+    }
+
+    @Test
+    fun `the scan config is logged when the scan starts`() = runTest {
+        createScanner()
+            .scan(filters = emptySet(), filterPolicy = ScanFilterPolicy.PROXIMITY_PAIRING)
+            .launchIn(backgroundScope)
+        runCurrent()
+
+        configLines() shouldHaveSize 1
+        configLines().single() shouldContain "filterPolicy=PROXIMITY_PAIRING"
+    }
+
+    @Test
+    fun `a recording started while the scan runs re-logs the config`() = runTest {
+        createScanner()
+            .scan(filters = emptySet(), filterPolicy = ScanFilterPolicy.MATCH_ALL)
+            .launchIn(backgroundScope)
+        runCurrent()
+
+        Bugs.isDebug.value = true
+        runCurrent()
+
+        configLines() shouldHaveSize 2
+        configLines().last().endsWith("(recording started)") shouldBe true
+    }
+
+    /**
+     * The re-emission suppresses the state it was already logged for, otherwise a scan starting
+     * inside a running recording writes the same line twice.
+     */
+    @Test
+    fun `a scan started during a recording logs the config once`() = runTest {
+        Bugs.isDebug.value = true
+
+        createScanner()
+            .scan(filters = emptySet(), filterPolicy = ScanFilterPolicy.PROXIMITY_PAIRING)
+            .launchIn(backgroundScope)
+        runCurrent()
+
+        configLines() shouldHaveSize 1
+    }
+}
@@ -45,6 +45,7 @@ class BlePodMonitorTest : BaseTest() {
        verify(exactly = 1) {
            fixture.bleScanner.scan(
                filters = any(),
+                filterPolicy = any(),
                scannerMode = any(),
                disableOffloadFiltering = any(),
                disableOffloadBatching = any(),
@@ -72,6 +73,7 @@ class BlePodMonitorTest : BaseTest() {
        verify(exactly = 2) {
            fixture.bleScanner.scan(
                filters = any(),
+                filterPolicy = any(),
                scannerMode = any(),
                disableOffloadFiltering = any(),
                disableOffloadBatching = any(),
@@ -90,6 +92,7 @@ class BlePodMonitorTest : BaseTest() {
            every {
                scan(
                    filters = any(),
+                    filterPolicy = any(),
                    scannerMode = any(),
                    disableOffloadFiltering = any(),
                    disableOffloadBatching = any(),