fix(debug): Make the short-recording warning clock-change safe and raise it to 10s

The "that recording looks very short" prompt measured duration against the wall clock, so any adjustment mid-recording decided it: an NTP sync or a manual clock change moving forward made a three-second recording look like an hour and skipped the prompt, moving backward trapped a long recording in it with no way past but "stop anyway". A live session now measures from a monotonic base taken at the start. Only a session resumed from the trigger file still uses the persisted wall time - that file has to survive reboots, which monotonic time does not - and a negative duration there fails open instead of warning. The threshold moves from 5s to 10s: a recording stopped that quickly holds nothing but the recorder starting and stopping, which costs a support round-trip to re-request. It stays a prompt, not a block, because a crash is logged and flushed immediately.
2026-09-14 18:26:11 -04:00 · 2026-08-03 08:30:33 +02:00
parent 26633b940d
commit 1dfed1c21c
2 changed files with 220 additions and 3 deletions
@@ -121,6 +121,7 @@ class RecorderModule @Inject constructor(
                            recorder = newRecorder,
                            currentLogDir = sessionDir,
                            recordingStartedAt = startTime,
+                            recordingStartedAtMonotonic = if (isResume) 0L else timeSource.elapsedRealtime(),
                            persistedLogDir = null,
                        )
                    } else if (!shouldRecord && isRecording) {
@@ -237,8 +238,17 @@ class RecorderModule @Inject constructor(
        if (!currentState.isRecording) return StopResult.NotRecording

        val logDir = currentState.currentLogDir ?: return StopResult.NotRecording
-        val elapsed = timeSource.currentTimeMillis() - currentState.recordingStartedAt
-        if (elapsed < MIN_RECORDING_MS) return StopResult.TooShort
+        val elapsed = if (currentState.recordingStartedAtMonotonic > 0L) {
+            // Live session: monotonic, immune to wall-clock adjustments mid-recording.
+            timeSource.elapsedRealtime() - currentState.recordingStartedAtMonotonic
+        } else {
+            // Resumed session: the trigger file persists wall time only — it has to survive reboots,
+            // which monotonic time does not.
+            timeSource.currentTimeMillis() - currentState.recordingStartedAt
+        }
+        // Negative = the wall clock moved backward across a resume; fail open (no warning) rather
+        // than trap the user in TooShort.
+        if (elapsed in 0 until MIN_RECORDING_MS) return StopResult.TooShort

        stopRecorder()
        val sessionId = DebugSessionManager.deriveSessionId(logDir)
@@ -256,6 +266,10 @@ class RecorderModule @Inject constructor(
        internal val recorder: Recorder? = null,
        val currentLogDir: File? = null,
        val recordingStartedAt: Long = 0L,
+        // Monotonic base for the duration heuristic, 0L when there is none: a resumed session's
+        // only start time is the persisted wall clock, and a monotonic value from a previous
+        // process or boot is meaningless.
+        val recordingStartedAtMonotonic: Long = 0L,
        internal val persistedLogDir: File? = null,
    ) {
        val isRecording: Boolean
@@ -288,7 +302,17 @@ class RecorderModule @Inject constructor(
    companion object {
        internal val TAG = logTag("Debug", "Log", "Recorder", "Module")
        private const val FORCE_FILE = "capod_force_debug_run"
-        private const val MIN_RECORDING_MS = 5_000L
+
+        /**
+         * Duration heuristic for "did you forget to reproduce the issue?". A recording stopped
+         * this quickly usually contains nothing but the recorder starting and stopping, which
+         * costs a support round-trip to re-request.
+         *
+         * It stays a prompt because short recordings can be perfectly valid: a crash is logged
+         * and flushed immediately, so the reproduction is already on disk. "Stop anyway" works —
+         * the [StopResult.TooShort] consumers stop via [stopRecorder], which has no duration check.
+         */
+        private const val MIN_RECORDING_MS = 10_000L

        // Budget for the header's diagnostics read.
        private const val HEADER_READ_TIMEOUT_MS = 5_000L
@@ -0,0 +1,193 @@
+package eu.darken.capod.common.debug.recording.core
+
+import android.content.Context
+import androidx.test.core.app.ApplicationProvider
+import eu.darken.capod.common.InstallId
+import eu.darken.capod.common.TimeSource
+import eu.darken.capod.common.debug.logging.FileLogger
+import eu.darken.capod.common.debug.logging.Logging
+import eu.darken.capod.common.upgrade.UpgradeDiagnostics
+import io.kotest.matchers.shouldBe
+import io.kotest.matchers.types.shouldBeInstanceOf
+import io.mockk.coEvery
+import io.mockk.mockk
+import kotlinx.coroutines.CoroutineScope
+import kotlinx.coroutines.Dispatchers
+import kotlinx.coroutines.SupervisorJob
+import kotlinx.coroutines.cancel
+import kotlinx.coroutines.flow.first
+import kotlinx.coroutines.runBlocking
+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 testhelpers.coroutine.TestDispatcherProvider
+import java.io.File
+import java.time.Duration
+import java.time.Instant
+
+/**
+ * The "that recording looks too short" prompt is a duration heuristic, and duration was measured
+ * against the wall clock. A clock adjustment mid-recording (NTP sync, the user changing the time)
+ * therefore either invented a long recording out of a short one or trapped a long recording in the
+ * warning. A live session now measures monotonically; only a session resumed from the trigger file
+ * has to fall back to the persisted wall time, because monotonic time does not survive a reboot.
+ */
+@RunWith(RobolectricTestRunner::class)
+@Config(sdk = [33], application = TestApplication::class)
+class RecorderModuleDurationTest : BaseTest() {
+
+    private fun buildModule(scope: CoroutineScope, timeSource: TimeSource): RecorderModule {
+        val diagnostics = mockk<UpgradeDiagnostics>()
+        coEvery { diagnostics.debugInfo() } returns null
+        return RecorderModule(
+            context = ApplicationProvider.getApplicationContext(),
+            appScope = scope,
+            dispatcherProvider = TestDispatcherProvider(Dispatchers.IO),
+            installId = mockk<InstallId>(relaxed = true),
+            timeSource = timeSource,
+            upgradeDiagnostics = diagnostics,
+        )
+    }
+
+    /**
+     * Real dispatchers: the module drives its recorder from its own scope, and the fake time source
+     * is what makes the duration deterministic instead of the scheduler. The recorder is stopped in
+     * a nested finally — a mid-test failure must not leave a live recorder behind, whose globally
+     * installed [FileLogger] would then write into every later test.
+     */
+    private fun withModule(
+        timeSource: TimeSource,
+        block: suspend (RecorderModule) -> Unit,
+    ) {
+        val moduleScope = CoroutineScope(Dispatchers.IO + SupervisorJob())
+        val fileLoggersBefore = Logging.loggers.filterIsInstance<FileLogger>()
+        var module: RecorderModule? = null
+        try {
+            try {
+                module = buildModule(moduleScope, timeSource)
+                runBlocking { block(module) }
+            } finally {
+                // Stop before cancelling: scope cancellation does NOT uninstall a running
+                // recorder's global FileLogger.
+                module?.let { runBlocking { it.stopRecorder() } }
+            }
+        } finally {
+            moduleScope.cancel()
+            // A leaked logger must fail THIS test, not poison later ones. Remove stragglers after
+            // asserting so one failure can't cascade.
+            val leaked = Logging.loggers.filterIsInstance<FileLogger>() - fileLoggersBefore.toSet()
+            leaked.forEach { Logging.remove(it) }
+            leaked shouldBe emptyList<FileLogger>()
+        }
+    }
+
+    // A session the module can resume from: the real two-line trigger file plus an existing dir.
+    private fun seedTriggerFile(startTime: Long): File {
+        val context = ApplicationProvider.getApplicationContext<Context>()
+        val sessionDir = File(context.getExternalFilesDir(null), "debug/logs/capod_resumed_session")
+        sessionDir.mkdirs()
+        File(context.getExternalFilesDir(null), "capod_force_debug_run")
+            .writeText("${sessionDir.absolutePath}\n$startTime")
+        return sessionDir
+    }
+
+    @Test
+    fun `an eight second recording warns`() {
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        withModule(timeSource) { module ->
+            module.startRecorder()
+
+            timeSource.advanceBy(Duration.ofSeconds(8))
+            module.requestStopRecorder() shouldBe RecorderModule.StopResult.TooShort
+            module.state.first().isRecording shouldBe true
+
+            // "Stop anyway" is the user's own next step, and past the threshold it stops cleanly.
+            timeSource.advanceBy(Duration.ofSeconds(3))
+            module.requestStopRecorder().shouldBeInstanceOf<RecorderModule.StopResult.Stopped>()
+            module.state.first().isRecording shouldBe false
+        }
+    }
+
+    @Test
+    fun `a ten second recording stops`() {
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        withModule(timeSource) { module ->
+            module.startRecorder()
+
+            timeSource.advanceBy(Duration.ofSeconds(10))
+
+            val result = module.requestStopRecorder()
+            result.shouldBeInstanceOf<RecorderModule.StopResult.Stopped>()
+            result.logDir.exists() shouldBe true
+            result.sessionId.isNotEmpty() shouldBe true
+            module.state.first().isRecording shouldBe false
+        }
+    }
+
+    @Test
+    fun `a backward wall-clock jump does not warn on a long recording`() {
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        withModule(timeSource) { module ->
+            module.startRecorder()
+
+            // Twelve real seconds of recording, and an NTP sync that moves the wall clock an hour
+            // back. Wall-clock measurement would report a negative duration here.
+            timeSource.elapsedRealtimeMs += 12_000L
+            timeSource.wallNow = timeSource.wallNow.minus(Duration.ofHours(1))
+
+            module.requestStopRecorder().shouldBeInstanceOf<RecorderModule.StopResult.Stopped>()
+        }
+    }
+
+    @Test
+    fun `a forward wall-clock jump does not skip the warning`() {
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        withModule(timeSource) { module ->
+            module.startRecorder()
+
+            // Three real seconds of recording, and a clock correction an hour forward. Wall-clock
+            // measurement would call this a one-hour recording and skip the prompt.
+            timeSource.elapsedRealtimeMs += 3_000L
+            timeSource.wallNow = timeSource.wallNow.plus(Duration.ofHours(1))
+
+            module.requestStopRecorder() shouldBe RecorderModule.StopResult.TooShort
+            module.state.first().isRecording shouldBe true
+        }
+    }
+
+    @Test
+    fun `a resumed session measures from the persisted start time`() {
+        // Resumed after a process death: there is no monotonic base to measure against, so the
+        // persisted wall-clock start is all the module has.
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        val startTime = timeSource.currentTimeMillis() - 8_000L
+        seedTriggerFile(startTime)
+
+        withModule(timeSource) { module ->
+            module.state.first { it.isRecording }
+
+            module.requestStopRecorder() shouldBe RecorderModule.StopResult.TooShort
+
+            timeSource.wallNow = Instant.ofEpochMilli(startTime + 10_000L)
+            module.requestStopRecorder().shouldBeInstanceOf<RecorderModule.StopResult.Stopped>()
+        }
+    }
+
+    @Test
+    fun `a resumed session with a future start time fails open`() {
+        // The persisted start lies in the future (the wall clock moved backward across the resume).
+        // A negative duration must not trap the user in the warning.
+        val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)
+        seedTriggerFile(timeSource.currentTimeMillis() + 60_000L)
+
+        withModule(timeSource) { module ->
+            module.state.first { it.isRecording }
+
+            module.requestStopRecorder().shouldBeInstanceOf<RecorderModule.StopResult.Stopped>()
+        }
+    }
+}