From 22ca3a2a46a0f6ed25747a92e9b3c79313af9696 Mon Sep 17 00:00:00 2001
From: darken <darken@darken.eu>
Date: Mon, 17 Aug 2026 11:47:29 +0200
Subject: [PATCH] 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.
---
 .../capod/common/bluetooth/BleScanner.kt      | 24 ++++++++++++-------
 1 file changed, 16 insertions(+), 8 deletions(-)

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 71a5118d..74ccc252 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
@@ -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))
             }