fix(bluetooth): Fix bogus scan-gap delays in debug logs

lastScanAt was read and written inside the log lambdas, which only run while
a logger is attached (log() checks Logging.hasReceivers first). In a release
build with recording off, the bookkeeping therefore never happened, so the
first delay of every debug recording reported the time since the *previous*
recording ended. Two logs from a support case opened with delay=878453ms and
delay=359983ms, which read as 14 and 6 minutes of suppressed scanning but
were just the gap between recordings.

The bookkeeping moves out of the lambdas, and the clock changes from
currentTimeMillis to elapsedRealtime so a wall-clock correction cannot
fabricate a gap either. That also puts the delay in the same boot-clock
domain as ScanResult.timestampNanos.
This commit is contained in:
darken
2026-08-17 13:00:02 +02:00
parent 92feea8a10
commit 22ca3a2a46
@@ -79,11 +79,22 @@ class BleScanner @Inject constructor(
}
val callback = object : ScanCallback() {
var lastScanAt = timeSource.currentTimeMillis()
// Updated outside the log lambdas below: those only run while a logger is attached, so
// folding the bookkeeping into them made the first delay of a debug recording measure
// the time since the *previous* recording ended instead of the actual callback gap.
// Monotonic clock, so a wall-clock correction can't fabricate a gap either.
var lastScanAt = timeSource.elapsedRealtime()
private fun takeDelay(): Long {
val now = timeSource.elapsedRealtime()
val delay = now - lastScanAt
lastScanAt = now
return delay
}
override fun onScanResult(callbackType: Int, result: ScanResult) {
val delay = takeDelay()
log(TAG, VERBOSE) {
val delay = timeSource.currentTimeMillis() - lastScanAt
lastScanAt = timeSource.currentTimeMillis()
"onScanResult(delay=${delay}ms, callbackType=$callbackType, ${result.logSummary()})"
}
@@ -91,11 +102,8 @@ class BleScanner @Inject constructor(
}
override fun onBatchScanResults(results: MutableList<ScanResult>) {
log(TAG, VERBOSE) {
val delay = timeSource.currentTimeMillis() - lastScanAt
lastScanAt = timeSource.currentTimeMillis()
"onBatchScanResults(delay=${delay}ms, ${results.logSummary()})"
}
val delay = takeDelay()
log(TAG, VERBOSE) { "onBatchScanResults(delay=${delay}ms, ${results.logSummary()})" }
trySend(filterResults(results))
}