From 1dfed1c21ce22017b17abed7c21c84642841fa4b Mon Sep 17 00:00:00 2001 From: darken Date: Sun, 2 Aug 2026 20:49:38 +0200 Subject: [PATCH] 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. --- .../debug/recording/core/RecorderModule.kt | 30 ++- .../core/RecorderModuleDurationTest.kt | 193 ++++++++++++++++++ 2 files changed, 220 insertions(+), 3 deletions(-) create mode 100644 app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDurationTest.kt diff --git a/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt b/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt index 3ecdc651..6d37d879 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt @@ -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 diff --git a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDurationTest.kt b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDurationTest.kt new file mode 100644 index 00000000..d513d86e --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDurationTest.kt @@ -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() + coEvery { diagnostics.debugInfo() } returns null + return RecorderModule( + context = ApplicationProvider.getApplicationContext(), + appScope = scope, + dispatcherProvider = TestDispatcherProvider(Dispatchers.IO), + installId = mockk(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() + 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() - fileLoggersBefore.toSet() + leaked.forEach { Logging.remove(it) } + leaked shouldBe emptyList() + } + } + + // 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() + 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() + 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() + 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() + } + } + + @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() + } + } + + @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() + } + } +}