diff --git a/app/src/main/java/eu/darken/capod/common/debug/recording/core/Recorder.kt b/app/src/main/java/eu/darken/capod/common/debug/recording/core/Recorder.kt index 84dcb311..f61be52e 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/recording/core/Recorder.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/recording/core/Recorder.kt @@ -6,8 +6,10 @@ import eu.darken.capod.common.debug.logging.Logging import eu.darken.capod.common.debug.logging.Logging.Priority.INFO import eu.darken.capod.common.debug.logging.log import eu.darken.capod.common.debug.logging.logTag +import kotlinx.coroutines.NonCancellable import kotlinx.coroutines.sync.Mutex import kotlinx.coroutines.sync.withLock +import kotlinx.coroutines.withContext import java.io.File import javax.inject.Inject @@ -35,12 +37,22 @@ class Recorder @Inject constructor( } suspend fun stop() = mutex.withLock { - fileLogger?.let { - log(TAG, INFO) { "Stopping file-logger-tree: $it" } - Logging.remove(it) - it.stop() - fileLogger = null - this.path = null + val logger = fileLogger ?: return@withLock + // A half-finished stop is worse than a failed one: the logger stays installed globally and + // keeps writing into a session nobody tracks any more. So cancellation cannot interrupt it, + // and a throw on the way out still uninstalls, closes and clears. + withContext(NonCancellable) { + try { + log(TAG, INFO) { "Stopping file-logger-tree: $logger" } + try { + Logging.remove(logger) + } finally { + logger.stop() + } + } finally { + fileLogger = null + this@Recorder.path = null + } } } 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 07fe4996..0a548b70 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 @@ -23,12 +23,16 @@ import eu.darken.capod.common.upgrade.UpgradeDiagnostics import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.NonCancellable +import kotlinx.coroutines.currentCoroutineContext +import kotlinx.coroutines.ensureActive import kotlinx.coroutines.flow.Flow import kotlinx.coroutines.flow.filter import kotlinx.coroutines.flow.first import kotlinx.coroutines.flow.launchIn import kotlinx.coroutines.flow.onEach import kotlinx.coroutines.plus +import kotlinx.coroutines.sync.Mutex +import kotlinx.coroutines.sync.withLock import kotlinx.coroutines.withContext import kotlinx.coroutines.withTimeoutOrNull import java.io.File @@ -49,6 +53,14 @@ class RecorderModule @Inject constructor( // advance the production bound. Same pattern as BillingCache.cacheTimeoutMs. internal var headerReadTimeoutMs: Long = HEADER_READ_TIMEOUT_MS + // Test seam: the recorder is constructed inline, so a failure at start or stop — the window this + // module's rollback exists for — has no other way in. Same pattern as [headerReadTimeoutMs]. + internal var recorderFactory: () -> Recorder = { Recorder(timeSource) } + + // Serializes the public start/stop entry points, observation included: two callers racing the + // same transition would otherwise each await a state the other one is about to overwrite. + private val startStopLock = Mutex() + @Volatile internal var currentLogDir: File? = null private set @@ -80,58 +92,107 @@ class RecorderModule @Inject constructor( internalState.updateBlocking { if (!isRecording && shouldRecord) { - val isResume = persistedLogDir != null && persistedLogDir.exists() - val sessionDir = if (isResume) { - log(TAG, INFO) { "Resuming recording into existing session: $persistedLogDir" } - persistedLogDir - } else { - createSessionDir() - } - val logFile = File(sessionDir, "core.log") - val newRecorder = Recorder(timeSource) - newRecorder.start(logFile) - - val startTime = when { - !isResume -> timeSource.currentTimeMillis() - recordingStartedAt > 0L -> recordingStartedAt - else -> timeSource.currentTimeMillis() - } - + // Everything between "a recorder exists" and "the state knows about it" is + // guarded: a throw anywhere in here would otherwise abandon a running + // recorder, kill this collector and wedge whoever awaits the state. + var newRecorder: Recorder? = null + var freshSessionDir: File? = null try { + val isResume = persistedLogDir != null && persistedLogDir.exists() + val sessionDir = if (isResume) { + log(TAG, INFO) { "Resuming recording into existing session: $persistedLogDir" } + persistedLogDir + } else { + createSessionDir().also { freshSessionDir = it } + } + val logFile = File(sessionDir, "core.log") + val startedRecorder = recorderFactory().also { newRecorder = it } + startedRecorder.start(logFile) + + val startTime = when { + !isResume -> timeSource.currentTimeMillis() + recordingStartedAt > 0L -> recordingStartedAt + else -> timeSource.currentTimeMillis() + } + if (!isResume) writeTriggerFile(sessionDir, startTime) logRecordingHeader() + + this@RecorderModule.currentLogDir = sessionDir + + copy( + recorder = startedRecorder, + currentLogDir = sessionDir, + recordingStartedAt = startTime, + recordingStartedAtMonotonic = if (isResume) null else timeSource.elapsedRealtime(), + persistedLogDir = null, + startFailure = null, + ) } catch (e: Exception) { - // The recorder is already live but not yet committed to the state: an exception - // escaping the header would abandon it where stopRecorder() can't reach it. + // Roll back BEFORE deciding what the failure means: even a genuine + // cancellation must not leave the started recorder behind. withContext(NonCancellable) { - try { - newRecorder.stop() - } catch (stopError: Exception) { - e.addSuppressed(stopError) + newRecorder?.let { + try { + it.stop() + } catch (stopError: Exception) { + e.addSuppressed(stopError) + } } this@RecorderModule.currentLogDir = null + // The trigger is written inside the guarded window and a resume + // reads a pre-existing one: leaving either behind re-attempts the + // dead session on every launch. + deleteTriggerFile() + // Only a dir WE created this attempt. Publishing the failure kicks + // off a session scan, and an empty dir left here would be + // auto-zipped as an orphan while the retry writes into it. A + // resumed dir is somebody's actual recording and is never deleted. + freshSessionDir?.let { + if (it.exists() && !it.deleteRecursively()) { + log(TAG, WARN) { "Failed to clean up session dir: $it" } + } + } } - throw e + // Our own scope dying is the one failure that SHOULD take this collector + // with it. Anything else — including a cancellation from inside the start + // work — becomes an ordinary failure, because rethrowing it here would + // kill the collector and wedge the module for the rest of the process. + currentCoroutineContext().ensureActive() + + log(TAG, ERROR) { "Failed to start recording: ${e.asLog()}" } + + copy( + shouldRecord = false, + startFailure = asStartFailure(e), + recorder = null, + currentLogDir = null, + recordingStartedAt = 0L, + recordingStartedAtMonotonic = null, + persistedLogDir = null, + ) } - - this@RecorderModule.currentLogDir = sessionDir - - copy( - recorder = newRecorder, - currentLogDir = sessionDir, - recordingStartedAt = startTime, - recordingStartedAtMonotonic = if (isResume) null else timeSource.elapsedRealtime(), - persistedLogDir = null, - ) } else if (!shouldRecord && isRecording) { - requireNotNull(recorder) { "Recorder is null despite isRecording" }.stop() - - if (triggerFile.exists() && !triggerFile.delete()) { - log(TAG, ERROR) { "Failed to delete trigger file" } + val stopError = try { + requireNotNull(recorder) { "Recorder is null despite isRecording" }.stop() + null + } catch (e: Exception) { + e } - this@RecorderModule.currentLogDir = null + withContext(NonCancellable) { + deleteTriggerFile() + this@RecorderModule.currentLogDir = null + } + + if (stopError != null) { + currentCoroutineContext().ensureActive() + // The state is cleared regardless: a stop that cannot complete must not + // also strand everyone awaiting the transition. A file logger that + // survived this is a leak, so it gets reported rather than hidden. + log(TAG, ERROR) { "Failed to stop recorder cleanly: ${stopError.asLog()}" } + } copy( recorder = null, @@ -152,8 +213,8 @@ class RecorderModule @Inject constructor( } // Header lines written into a freshly started recording. Runs AFTER the recorder is live, so - // every read here is diagnostics-only and must never propagate: a failure would abort the state - // update and leave a RUNNING recorder that the module no longer knows about. + // every read here is diagnostics-only and must never propagate: a failure that escapes costs + // the user the whole recording, which the caller's start branch then has to roll back. private suspend fun logRecordingHeader() { log(TAG, INFO) { "Build.Fingerprint: ${Build.FINGERPRINT}" } log(TAG, INFO) { "BuildConfig.Versions: ${BuildConfigWrap.VERSION_DESCRIPTION}" } @@ -185,11 +246,34 @@ class RecorderModule @Inject constructor( */ private class HeaderRead(val value: T) + /** + * A start failure that arrived as a [CancellationException] while this module's own scope was + * still alive — a bounded read inside the start work timing out, for example. Handing that to + * the caller unchanged would cancel THEM for a failure that is not theirs, so it is converted + * into an ordinary one. + */ + class RecordingStartFailedException(cause: Throwable) : IllegalStateException("Failed to start recording", cause) + + private fun asStartFailure(error: Exception): Throwable = when (error) { + is CancellationException -> RecordingStartFailedException(error) + else -> error + } + + private fun deleteTriggerFile() { + try { + if (triggerFile.exists() && !triggerFile.delete()) { + log(TAG, ERROR) { "Failed to delete trigger file" } + } + } catch (e: Exception) { + log(TAG, ERROR) { "Failed to delete trigger file: ${e.asLog()}" } + } + } + private fun createSessionDir(): File { val timestamp = timeSource.now().atZone(java.time.ZoneOffset.UTC) .format(java.time.format.DateTimeFormatter.ofPattern("yyyyMMdd'T'HHmmss'Z'")) val installIdPrefix = installId.id.take(8) - val dirName = "capod_${BuildConfigWrap.VERSION_NAME}_${timestamp}_$installIdPrefix" + val baseName = "capod_${BuildConfigWrap.VERSION_NAME}_${timestamp}_$installIdPrefix" val primaryParent = try { val dir = File(context.getExternalFilesDir(null), "debug/logs") @@ -201,7 +285,15 @@ class RecorderModule @Inject constructor( } val parent = primaryParent ?: File(context.cacheDir, "debug/logs").also { it.mkdirs() } - val sessionDir = File(parent, dirName) + + // The name is timestamped to the second, so two sessions within the same second — a retry + // after a failed start, most of all — would land in one directory and interleave their logs. + var sessionDir = File(parent, baseName) + var collision = 1 + while (sessionDir.exists()) { + collision++ + sessionDir = File(parent, "${baseName}_$collision") + } sessionDir.mkdirs() log(TAG) { "Created session dir: $sessionDir" } @@ -217,15 +309,21 @@ class RecorderModule @Inject constructor( File(context.cacheDir, "debug/logs"), ) - suspend fun startRecorder(): File { + suspend fun startRecorder(): File = startStopLock.withLock { + // Clearing the failure is part of the request: a stale one from an earlier attempt would + // otherwise be reported as the outcome of this one. internalState.updateBlocking { - copy(shouldRecord = true) + copy(shouldRecord = true, startFailure = null) } - val state = internalState.flow.filter { it.isRecording }.first() - return requireNotNull(state.currentLogDir) { "Recording state has no logDir" } + // A start that cannot succeed has to settle the wait too, or the caller sits here forever. + val state = internalState.flow.first { it.isRecording || it.startFailure != null } + state.startFailure?.let { throw it } + requireNotNull(state.currentLogDir) { "Recording state has no logDir" } } - suspend fun stopRecorder(): File? { + suspend fun stopRecorder(): File? = startStopLock.withLock { stopRecorderUnlocked() } + + private suspend fun stopRecorderUnlocked(): File? { val currentDir = internalState.value().currentLogDir ?: return null internalState.updateBlocking { copy(shouldRecord = false) @@ -234,11 +332,11 @@ class RecorderModule @Inject constructor( return currentDir } - suspend fun requestStopRecorder(): StopResult { + suspend fun requestStopRecorder(): StopResult = startStopLock.withLock { val currentState = internalState.value() - if (!currentState.isRecording) return StopResult.NotRecording + if (!currentState.isRecording) return@withLock StopResult.NotRecording - val logDir = currentState.currentLogDir ?: return StopResult.NotRecording + val logDir = currentState.currentLogDir ?: return@withLock StopResult.NotRecording val startedAtMono = currentState.recordingStartedAtMonotonic val elapsed = if (startedAtMono != null) { // Live session: monotonic, immune to wall-clock adjustments mid-recording. @@ -250,11 +348,11 @@ class RecorderModule @Inject constructor( } // 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 + if (elapsed in 0 until MIN_RECORDING_MS) return@withLock StopResult.TooShort - stopRecorder() + stopRecorderUnlocked() val sessionId = DebugSessionManager.deriveSessionId(logDir) - return StopResult.Stopped(logDir, sessionId) + StopResult.Stopped(logDir, sessionId) } sealed class StopResult { @@ -273,6 +371,10 @@ class RecorderModule @Inject constructor( // process or boot is meaningless. internal val recordingStartedAtMonotonic: Long? = null, internal val persistedLogDir: File? = null, + // Why the last start attempt did not produce a recording. Carried as the Throwable itself: + // two consecutive failures are distinct instances, so the state flow's distinctUntilChanged + // cannot swallow the second one. + val startFailure: Throwable? = null, ) { val isRecording: Boolean get() = recorder != null diff --git a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDiagnosticsTest.kt b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDiagnosticsTest.kt index 67a09543..cb52a05c 100644 --- a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDiagnosticsTest.kt +++ b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDiagnosticsTest.kt @@ -8,6 +8,7 @@ import eu.darken.capod.common.coroutine.DispatcherProvider 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.assertions.throwables.shouldThrow import io.kotest.matchers.longs.shouldBeLessThan import io.kotest.matchers.nulls.shouldBeNull import io.kotest.matchers.nulls.shouldNotBeNull @@ -154,13 +155,12 @@ class RecorderModuleDiagnosticsTest : BaseTest() { /** * Cancellation is the one thing the guarded header read deliberately rethrows, so it is one of - * the failures that can abort the state update. The recorder is already live at that point: it - * has to be stopped on the way out, or it keeps writing into a session the module no longer - * tracks. + * the failures that can abort the start. The recorder is already live at that point: it has to + * be stopped on the way out, or it keeps writing into a session the module no longer tracks. * - * The start is launched, not awaited: an aborted update never flips isRecording, so - * startRecorder() stays suspended. The virtual-time delay is what lets the module's own - * background collectors run to completion. + * The cancellation is foreign — this module's own scope is alive — so it is reported to the + * caller as an ordinary start failure rather than rethrown. The start can therefore be awaited + * directly: it settles instead of suspending forever on a state nobody publishes. */ @Test fun `a cancelled upgrade-diagnostics read stops the recorder instead of leaking it`() = runTest { @@ -170,8 +170,7 @@ class RecorderModuleDiagnosticsTest : BaseTest() { val module = buildModule(backgroundScope, diagnostics) - backgroundScope.launch { module.startRecorder() } - delay(1_000) + shouldThrow { module.startRecorder() } coVerify { diagnostics.debugInfo() } module.state.first().isRecording shouldBe false diff --git a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt new file mode 100644 index 00000000..29c512fa --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt @@ -0,0 +1,401 @@ +package eu.darken.capod.common.debug.recording.core + +import android.content.Context +import androidx.test.core.app.ApplicationProvider +import eu.darken.capod.common.BuildConfigWrap +import eu.darken.capod.common.InstallId +import eu.darken.capod.common.SystemTimeSource +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.assertions.throwables.shouldThrow +import io.kotest.matchers.collections.shouldBeEmpty +import io.kotest.matchers.collections.shouldHaveSize +import io.kotest.matchers.nulls.shouldBeNull +import io.kotest.matchers.nulls.shouldNotBeNull +import io.kotest.matchers.shouldBe +import io.kotest.matchers.shouldNotBe +import io.kotest.matchers.types.shouldBeInstanceOf +import io.mockk.coEvery +import io.mockk.every +import io.mockk.mockk +import io.mockk.mockkObject +import io.mockk.unmockkObject +import kotlinx.coroutines.CancellationException +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.cancel +import kotlinx.coroutines.delay +import kotlinx.coroutines.flow.first +import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.withTimeout +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 testhelpers.coroutine.TestDispatcherProvider +import java.io.File +import java.io.IOException +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicReference + +/** + * Starting a recording is several steps wide — create a directory, start a recorder, persist the + * trigger, write the header — and only the last of them commits the recorder into the module's + * state. A failure in that window used to escape the reactive collector, which killed the collector + * for the rest of the process: the recorder kept writing where nothing could stop it, the trigger + * file survived to re-attempt the dead session on every launch, and startRecorder() waited for a + * state nobody would ever publish. The debug log toggle was then dead until the app was reinstalled. + * + * A start that cannot succeed has to fail LOUDLY and leave the module usable. + */ +@RunWith(RobolectricTestRunner::class) +@Config(sdk = [33], application = TestApplication::class) +class RecorderModuleStartFailureTest : BaseTest() { + + private val headerReads = AtomicInteger(0) + private var buildConfigMocked = false + + private val context: Context + get() = ApplicationProvider.getApplicationContext() + + private val triggerFile: File + get() = File(context.getExternalFilesDir(null), "capod_force_debug_run") + + private val externalLogsDir: File + get() = File(context.getExternalFilesDir(null), "debug/logs") + + @Before + fun cleanRecorderFiles() { + triggerFile.delete() + externalLogsDir.deleteRecursively() + File(context.cacheDir, "debug/logs").deleteRecursively() + } + + @After + fun restoreBuildConfig() { + if (buildConfigMocked) unmockkObject(BuildConfigWrap) + } + + /** + * The one read in the start work that is deliberately NOT guarded: the header's build + * description. Everything the header pulls from injected sources is caught and downgraded to a + * warning, so it cannot drive this window at all — see [RecorderModuleDiagnosticsTest]. + * + * Doubles as the attempt counter: [headerReads] tells a single failed attempt apart from a + * collector that keeps re-entering the start branch. + */ + private fun failTheHeaderRead() { + mockkObject(BuildConfigWrap) + buildConfigMocked = true + every { BuildConfigWrap.VERSION_DESCRIPTION } answers { + headerReads.incrementAndGet() + throw IllegalStateException("build info unreadable") + } + } + + private fun repairTheHeaderRead() { + every { BuildConfigWrap.VERSION_DESCRIPTION } answers { + headerReads.incrementAndGet() + "v1.2.3 (4) ~ FOSS/DEV" + } + } + + private inner class Modules( + private val scope: CoroutineScope, + private val timeSource: TimeSource, + private val upgradeDiagnostics: UpgradeDiagnostics, + ) { + val created = mutableListOf() + + fun create(recorderFactory: (() -> Recorder)? = null): RecorderModule = RecorderModule( + context = ApplicationProvider.getApplicationContext(), + appScope = scope, + dispatcherProvider = TestDispatcherProvider(Dispatchers.IO), + installId = mockk(relaxed = true), + timeSource = timeSource, + upgradeDiagnostics = upgradeDiagnostics, + ).also { module -> + recorderFactory?.let { module.recorderFactory = it } + created.add(module) + } + } + + /** + * Real dispatchers: the module drives the start from its own scope, and the whole point here is + * that a failed start settles instead of hanging — virtual time would hide a wedge rather than + * expose it. The envelope is what turns a regression into a failure in seconds instead of a CI + * runner stuck until the job timeout, which is what the pre-fix module did. + */ + private fun withModules( + timeSource: TimeSource = SystemTimeSource, + upgradeDiagnostics: UpgradeDiagnostics = mockk().apply { + coEvery { debugInfo() } returns null + }, + block: suspend (Modules) -> Unit, + ) { + val moduleScope = CoroutineScope(Dispatchers.IO + SupervisorJob()) + val fileLoggersBefore = Logging.loggers.filterIsInstance() + val modules = Modules(moduleScope, timeSource, upgradeDiagnostics) + try { + try { + runBlocking { withTimeout(BLOCK_TIMEOUT_MS) { block(modules) } } + } finally { + // Stop before cancelling: scope cancellation does NOT uninstall a running + // recorder's global FileLogger. A wedged stop must not hang cleanup either; the + // FileLogger assertion below then fails the test with the real signal. + modules.created.forEach { module -> + runBlocking { + try { + withTimeout(STOP_TIMEOUT_MS) { module.stopRecorder() } + } catch (e: Exception) { + // the leak assertion below reports it + } + } + } + } + } 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 resumes at startup: the real two-line trigger file plus an existing dir. + private fun seedResumableSession(startTime: Long): File { + val sessionDir = File(externalLogsDir, "capod_1.0_20260101T000000Z_seeded").also { it.mkdirs() } + File(sessionDir, "core.log").writeText("earlier recording\n") + triggerFile.writeText("${sessionDir.absolutePath}\n$startTime") + return sessionDir + } + + @Test + fun `a failed start surfaces the error instead of hanging`() { + failTheHeaderRead() + + withModules { modules -> + val module = modules.create() + + val error = shouldThrow { module.startRecorder() } + error.message shouldBe "build info unreadable" + + val state = module.state.first() + state.isRecording shouldBe false + // Reset on failure, or the every-state collector walks straight back into the start + // branch and retries forever. + state.shouldRecord shouldBe false + state.currentLogDir.shouldBeNull() + state.recordingStartedAt shouldBe 0L + state.startFailure.shouldNotBeNull() + module.currentLogDir.shouldBeNull() + // A trigger left behind would re-attempt this dead session on every app launch. + triggerFile.exists() shouldBe false + } + } + + @Test + fun `the recorder recovers after a failed start`() { + failTheHeaderRead() + + withModules { modules -> + val module = modules.create() + shouldThrow { module.startRecorder() } + + repairTheHeaderRead() + + val logDir = module.startRecorder() + logDir.exists() shouldBe true + val recording = module.state.first { it.isRecording } + recording.currentLogDir shouldBe logDir + // A stale failure must not be reported as the outcome of the attempt that succeeded. + recording.startFailure.shouldBeNull() + module.currentLogDir shouldBe logDir + triggerFile.exists() shouldBe true + + module.stopRecorder() shouldBe logDir + module.state.first().isRecording shouldBe false + triggerFile.exists() shouldBe false + } + } + + /** + * A [CancellationException] out of the start work does NOT mean this module's scope is going + * away — a bounded read timing out looks exactly like this. Rethrowing it would kill the state + * collector permanently, which is the very wedge this class exists to prevent, so it is + * converted into an ordinary failure instead. + */ + @Test + fun `a foreign cancellation during start does not kill the recorder for good`() { + // Atomic: the read runs on the module's own thread, the test flips it from its own. + val readFailure = AtomicReference(CancellationException("bounded read gave up")) + val diagnostics = mockk() + coEvery { diagnostics.debugInfo() } coAnswers { + readFailure.get()?.let { throw it } + null + } + + withModules(upgradeDiagnostics = diagnostics) { modules -> + val module = modules.create() + + // Not a CancellationException: handing that to the caller would cancel THEM. + shouldThrow { module.startRecorder() } + module.state.first().isRecording shouldBe false + + readFailure.set(null) + + // Non-vacuity: with a rethrow the collector would be dead here and this would hang + // until the envelope kills the test. + val logDir = module.startRecorder() + logDir.exists() shouldBe true + module.state.first { it.isRecording }.currentLogDir shouldBe logDir + } + } + + @Test + fun `a failed start is attempted once and then settles`() { + failTheHeaderRead() + + withModules { modules -> + val module = modules.create() + + shouldThrow { module.startRecorder() } + headerReads.get() shouldBe 1 + + // The collector reacts to EVERY state emission and re-derives the branch from + // shouldRecord, so a failure that left shouldRecord set would spin here. + delay(SETTLE_MS) + headerReads.get() shouldBe 1 + module.state.first().shouldRecord shouldBe false + + // One attempt per request, not one per state emission. + shouldThrow { module.startRecorder() } + headerReads.get() shouldBe 2 + delay(SETTLE_MS) + headerReads.get() shouldBe 2 + } + } + + /** + * A failure emission makes [DebugSessionManager] rescan, and an abandoned session dir would be + * picked up as an orphan and auto-zipped — while a retry within the same second writes into it. + * The dir the failed attempt created has to be gone before the failure is published. + */ + @Test + fun `a failed start leaves no session dir for the manager to pick up`() { + failTheHeaderRead() + + withModules(timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)) { modules -> + val module = modules.create() + + shouldThrow { module.startRecorder() } + + externalLogsDir.listFiles()?.toList().orEmpty().shouldBeEmpty() + DebugSessionManager.scanSessions(module.getLogDirectories()).shouldBeEmpty() + + repairTheHeaderRead() + + // Fixed clock: the retry hits the exact same timestamped name the dead attempt used. + val logDir = module.startRecorder() + logDir.exists() shouldBe true + + val sessions = DebugSessionManager.scanSessions(module.getLogDirectories(), activeDir = logDir) + sessions shouldHaveSize 1 + sessions.single().shouldBeInstanceOf() + } + } + + @Test + fun `a second recording in the same second gets its own session dir`() { + withModules(timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)) { modules -> + val module = modules.create() + + val first = module.startRecorder() + module.stopRecorder() shouldBe first + + // Same fixed clock, so the name is identical — appending into the finished session + // would interleave two recordings in one core.log. + val second = module.startRecorder() + second shouldNotBe first + first.exists() shouldBe true + second.exists() shouldBe true + } + } + + /** + * The stop side of the same window: a recorder that cannot stop must not strand the state. + * Everything awaiting the transition — stopRecorder(), requestStopRecorder(), the UI's + * isRecording — depends on the cleared state being committed anyway. + */ + @Test + fun `a recorder that fails to stop still clears the recording state`() { + val brokenRecorder = mockk(relaxed = true) + coEvery { brokenRecorder.stop() } throws IOException("log writer wedged") + + withModules { modules -> + val module = modules.create(recorderFactory = { brokenRecorder }) + + val logDir = module.startRecorder() + triggerFile.exists() shouldBe true + + module.stopRecorder() shouldBe logDir + + val state = module.state.first() + state.isRecording shouldBe false + state.currentLogDir.shouldBeNull() + state.recordingStartedAt shouldBe 0L + state.recordingStartedAtMonotonic.shouldBeNull() + module.currentLogDir.shouldBeNull() + triggerFile.exists() shouldBe false + } + } + + /** + * The boot path starts a recording without anyone calling startRecorder(): a trigger file left + * from a previous run makes the module resume on construction. If that resume fails and the + * trigger survives, every single launch re-attempts the same dead session. + */ + @Test + fun `a failed resume at boot clears the trigger instead of retrying every launch`() { + val timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L) + val sessionDir = seedResumableSession(timeSource.currentTimeMillis() - 20_000L) + failTheHeaderRead() + + withModules(timeSource = timeSource) { modules -> + val module = modules.create() + + module.state.first { it.startFailure != null } + module.state.first().isRecording shouldBe false + module.currentLogDir.shouldBeNull() + triggerFile.exists() shouldBe false + // A resumed dir holds a real earlier recording — rollback deletes only what it created. + sessionDir.exists() shouldBe true + File(sessionDir, "core.log").exists() shouldBe true + headerReads.get() shouldBe 1 + + // The next launch: nothing left to resume, so no second attempt at the dead session. + val nextLaunch = modules.create() + nextLaunch.state.first().shouldRecord shouldBe false + delay(SETTLE_MS) + headerReads.get() shouldBe 1 + } + } + + companion object { + private const val BLOCK_TIMEOUT_MS = 15_000L + private const val STOP_TIMEOUT_MS = 10_000L + + // Real time, not virtual: long enough for a retry loop to show itself, short enough to stay + // well inside the block envelope. + private const val SETTLE_MS = 500L + } +} diff --git a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStateTest.kt b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStateTest.kt index 17fdb41c..353c0a52 100644 --- a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStateTest.kt +++ b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStateTest.kt @@ -38,5 +38,10 @@ class RecorderModuleStateTest : BaseTest() { fun `persistedLogDir is null`() { RecorderModule.State().persistedLogDir shouldBe null } + + @Test + fun `startFailure is null`() { + RecorderModule.State().startFailure shouldBe null + } } }