From 39a6c3c89f30727a8eccfcc573f1da52bd430fa9 Mon Sep 17 00:00:00 2001 From: darken Date: Mon, 31 Aug 2026 18:45:20 +0200 Subject: [PATCH] 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. --- .../capod/common/bluetooth/BleScanner.kt | 89 +++++++-- .../common/bluetooth/ScanFilterPolicy.kt | 3 + .../capod/monitor/core/ble/BlePodMonitor.kt | 5 + .../bluetooth/BleScannerConfigLogTest.kt | 184 ++++++++++++++++++ .../monitor/core/ble/BlePodMonitorTest.kt | 3 + 5 files changed, 270 insertions(+), 14 deletions(-) create mode 100644 app/src/main/java/eu/darken/capod/common/bluetooth/ScanFilterPolicy.kt create mode 100644 app/src/test/java/eu/darken/capod/common/bluetooth/BleScannerConfigLogTest.kt diff --git a/app/src/main/java/eu/darken/capod/common/bluetooth/BleScanner.kt b/app/src/main/java/eu/darken/capod/common/bluetooth/BleScanner.kt index 74ccc252..2f08178f 100644 --- a/app/src/main/java/eu/darken/capod/common/bluetooth/BleScanner.kt +++ b/app/src/main/java/eu/darken/capod/common/bluetooth/BleScanner.kt @@ -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, + 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"}" + } +} diff --git a/app/src/main/java/eu/darken/capod/common/bluetooth/ScanFilterPolicy.kt b/app/src/main/java/eu/darken/capod/common/bluetooth/ScanFilterPolicy.kt new file mode 100644 index 00000000..b6feda46 --- /dev/null +++ b/app/src/main/java/eu/darken/capod/common/bluetooth/ScanFilterPolicy.kt @@ -0,0 +1,3 @@ +package eu.darken.capod.common.bluetooth + +enum class ScanFilterPolicy { PROXIMITY_PAIRING, MATCH_ALL } diff --git a/app/src/main/java/eu/darken/capod/monitor/core/ble/BlePodMonitor.kt b/app/src/main/java/eu/darken/capod/monitor/core/ble/BlePodMonitor.kt index b92175ed..8dabc6f4 100644 --- a/app/src/main/java/eu/darken/capod/monitor/core/ble/BlePodMonitor.kt +++ b/app/src/main/java/eu/darken/capod/monitor/core/ble/BlePodMonitor.kt @@ -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, diff --git a/app/src/test/java/eu/darken/capod/common/bluetooth/BleScannerConfigLogTest.kt b/app/src/test/java/eu/darken/capod/common/bluetooth/BleScannerConfigLogTest.kt new file mode 100644 index 00000000..ad3aeb30 --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/bluetooth/BleScannerConfigLogTest.kt @@ -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() + private val logCapture = object : Logging.Logger { + override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map?) { + 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(relaxed = true).apply { + every { isOffloadedFilteringSupported } returns offloadFilteringSupported + every { isOffloadedScanBatchingSupported } returns offloadBatchingSupported + } + val leScanner = mockk(relaxed = true) + val bluetoothManager = mockk().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 + } +} diff --git a/app/src/test/java/eu/darken/capod/monitor/core/ble/BlePodMonitorTest.kt b/app/src/test/java/eu/darken/capod/monitor/core/ble/BlePodMonitorTest.kt index df3e5836..a059032f 100644 --- a/app/src/test/java/eu/darken/capod/monitor/core/ble/BlePodMonitorTest.kt +++ b/app/src/test/java/eu/darken/capod/monitor/core/ble/BlePodMonitorTest.kt @@ -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(),