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