diff --git a/app/src/main/java/eu/darken/capod/common/debug/recording/core/DebugSessionManager.kt b/app/src/main/java/eu/darken/capod/common/debug/recording/core/DebugSessionManager.kt index 7162c66b..2ca7de45 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/recording/core/DebugSessionManager.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/recording/core/DebugSessionManager.kt @@ -16,6 +16,7 @@ import kotlinx.coroutines.flow.MutableSharedFlow import kotlinx.coroutines.flow.MutableStateFlow import kotlinx.coroutines.flow.combine import kotlinx.coroutines.flow.launchIn +import kotlinx.coroutines.flow.map import kotlinx.coroutines.flow.onEach import kotlinx.coroutines.flow.onStart import kotlinx.coroutines.flow.update @@ -48,7 +49,18 @@ class DebugSessionManager @Inject constructor( val recorderState: Flow get() = recorderModule.state - val sessions: Flow> = combine( + /** + * A scan together with the recorder state it was taken against. The two travel as one value on + * purpose: the reconciliation below has to know whether the snapshot it reacts to was taken + * mid-start, and observing the recorder state as a second flow would let a scan meet a state + * that is not the one it was derived from. + */ + private data class Scan( + val sessions: List, + val startPending: Boolean, + ) + + private val scans: Flow = combine( recorderModule.state, zippingIds, failedZipIds, @@ -59,12 +71,27 @@ class DebugSessionManager @Inject constructor( activeDir = recorderState.currentLogDir, recordingStartedAt = recorderState.recordingStartedAt, ) - applyOverlays(raw, zipping, failedZips) + Scan( + sessions = applyOverlays(raw, zipping, failedZips), + startPending = recorderState.isStartPending, + ) }.replayingShare(appScope) + val sessions: Flow> = scans.map { it.sessions } + init { - sessions.onEach { allSessions -> - val orphans = findOrphans(allSessions, zippingIds.value) + scans.onEach { scan -> + // A start publishes its session dir only once the recorder is live. Until then the dir + // is already on disk with no activeDir to match it, so it scans as an orphan — zipping + // it would compress a directory the recorder is writing into, and race the rollback + // that deletes it if the start then fails. Only NEW zips are held back; anything + // already running keeps going. Reconciliation resumes on the next emission, once the + // state is recording or the failure has settled. + if (scan.startPending) { + log(TAG) { "A start is in flight, deferring orphan reconciliation" } + return@onEach + } + val orphans = findOrphans(scan.sessions, zippingIds.value) orphans.forEach { (id, dir) -> if (pendingAutoZips.add(id)) { log(TAG, INFO) { "Orphan session detected, auto-zipping: $id" } 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 0a548b70..1f5fb75c 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 @@ -290,7 +290,7 @@ class RecorderModule @Inject constructor( // 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()) { + while (sessionDir.isNameTaken()) { collision++ sessionDir = File(parent, "${baseName}_$collision") } @@ -300,6 +300,15 @@ class RecorderModule @Inject constructor( return sessionDir } + /** + * The session ID is derived from this name, so a sibling archive claims it just as much as a + * directory does: the dir of a zipped session is gone, and reusing its name would hand a new + * recording the identity of the archive next to it. A '.zip.tmp' is a zip still being written. + */ + private fun File.isNameTaken(): Boolean = exists() || + File(parentFile, "$name.zip").exists() || + File(parentFile, "$name.zip.tmp").exists() + internal fun getLogDirectories(): List = listOfNotNull( try { context.getExternalFilesDir(null)?.let { File(it, "debug/logs") } @@ -379,6 +388,14 @@ class RecorderModule @Inject constructor( val isRecording: Boolean get() = recorder != null + /** + * A start that was requested but has not committed yet. Its session dir already exists on + * disk while no field here points at it, so anything reconciling the log directory against + * this state has to treat the window as "not settled" rather than as a stale leftover. + */ + internal val isStartPending: Boolean + get() = shouldRecord && !isRecording + val currentLogPath: File? get() = recorder?.path } 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 index 29c512fa..1eb477c2 100644 --- 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 @@ -12,6 +12,7 @@ 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.longs.shouldBeGreaterThan import io.kotest.matchers.nulls.shouldBeNull import io.kotest.matchers.nulls.shouldNotBeNull import io.kotest.matchers.shouldBe @@ -26,10 +27,12 @@ import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.async import kotlinx.coroutines.cancel import kotlinx.coroutines.delay import kotlinx.coroutines.flow.first import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.withContext import kotlinx.coroutines.withTimeout import org.junit.After import org.junit.Before @@ -43,6 +46,9 @@ import testhelpers.TestTimeSource import testhelpers.coroutine.TestDispatcherProvider import java.io.File import java.io.IOException +import java.util.concurrent.CopyOnWriteArrayList +import java.util.concurrent.CountDownLatch +import java.util.concurrent.TimeUnit import java.util.concurrent.atomic.AtomicInteger import java.util.concurrent.atomic.AtomicReference @@ -109,7 +115,7 @@ class RecorderModuleStartFailureTest : BaseTest() { } private inner class Modules( - private val scope: CoroutineScope, + val scope: CoroutineScope, private val timeSource: TimeSource, private val upgradeDiagnostics: UpgradeDiagnostics, ) { @@ -126,6 +132,16 @@ class RecorderModuleStartFailureTest : BaseTest() { recorderFactory?.let { module.recorderFactory = it } created.add(module) } + + // A REAL manager on the module's own scope: its reconciliation is a live collector reacting + // to every recorder state, and the window this file is about only exists while it runs. + // A static scan cannot show whether that collector zips a directory it should not. + fun createManager(module: RecorderModule, zipper: DebugLogZipper) = DebugSessionManager( + appScope = scope, + dispatcherProvider = TestDispatcherProvider(Dispatchers.IO), + recorderModule = module, + debugLogZipper = zipper, + ) } /** @@ -286,31 +302,84 @@ class RecorderModuleStartFailureTest : BaseTest() { } /** - * 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. + * The start is only committed into the state once the recorder is live, so for the whole window + * before that the session dir sits on disk with nothing pointing at it: a scan sees a directory + * with a non-empty core.log and no sibling zip, which is exactly an orphan. A live manager + * scanning in that window would compress the directory the recorder is writing into, and the + * rollback of a failing start would then race the zipper — with a leftover archive left behind + * to hand the retry the very session ID that just died. + * + * The header read is blocked to hold the window open, the same seam [RecorderModuleDiagnosticsTest] + * uses to exercise it. */ @Test - fun `a failed start leaves no session dir for the manager to pick up`() { - failTheHeaderRead() + fun `a live manager does not zip a session dir while its start is still in flight`() { + val headerBlocked = CountDownLatch(1) + val releaseHeader = CountDownLatch(1) + mockkObject(BuildConfigWrap) + buildConfigMocked = true + every { BuildConfigWrap.VERSION_DESCRIPTION } answers { + headerReads.incrementAndGet() + headerBlocked.countDown() + releaseHeader.await(AWAIT_TIMEOUT_MS, TimeUnit.MILLISECONDS) + throw IllegalStateException("build info unreadable") + } - withModules(timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)) { modules -> + val zipped = CopyOnWriteArrayList() + val zipper = mockk() + every { zipper.zip(any()) } answers { + val dir = firstArg() + zipped.add(dir) + // Produce the archive for real: without it the reconciliation would find the same + // orphan on every rescan and spin. + File(dir.parentFile, "${dir.name}.zip").also { it.writeText("zipped") } + } + + withModules { modules -> val module = modules.create() + val manager = modules.createManager(module, zipper) - shouldThrow { module.startRecorder() } + val start = modules.scope.async { module.startRecorder() } + withContext(Dispatchers.IO) { headerBlocked.await(AWAIT_TIMEOUT_MS, TimeUnit.MILLISECONDS) } shouldBe true - externalLogsDir.listFiles()?.toList().orEmpty().shouldBeEmpty() - DebugSessionManager.scanSessions(module.getLogDirectories()).shouldBeEmpty() + val inFlight = externalLogsDir.listFiles()?.toList().orEmpty().single { it.isDirectory } + // The recorder is already writing, so this is a Ready orphan to a scan — not a broken + // session it would skip anyway. + File(inFlight, "core.log").length() shouldBeGreaterThan 0L - repairTheHeaderRead() + // A finished session from before: the gate defers it too, but it is not the one at risk, + // so it doubles as the proof that the collector is alive and reaches the auto-zip path. + val bystander = File(externalLogsDir, "capod_1.0_20250101T000000Z_bystander").also { it.mkdirs() } + File(bystander, "core.log").writeText("an earlier session\n") - // Fixed clock: the retry hits the exact same timestamped name the dead attempt used. - val logDir = module.startRecorder() - logDir.exists() shouldBe true + // The delayed scan of the failure: it runs while the start is still pending, so the + // in-flight dir has no activeDir to match and looks like everybody else's leftovers. + manager.refresh() + val seen = withTimeout(AWAIT_TIMEOUT_MS) { + manager.sessions.first { scan -> scan.any { it.displayName == inFlight.name } } + } + // Non-vacuity: the manager really did scan both dirs, and in a shape its reconciliation + // would have zipped. The gate is what stopped it, not a scan that never happened. + seen shouldHaveSize 2 + seen.forEach { it.shouldBeInstanceOf() } - val sessions = DebugSessionManager.scanSessions(module.getLogDirectories(), activeDir = logDir) - sessions shouldHaveSize 1 - sessions.single().shouldBeInstanceOf() + delay(SETTLE_MS) + zipped.shouldBeEmpty() + + releaseHeader.countDown() + shouldThrow { start.await() } + module.state.first { it.startFailure != null } + + // The rollback ran to completion, uncontested: no zipper had a claim on the directory. + inFlight.exists() shouldBe false + File(externalLogsDir, "${inFlight.name}.zip").exists() shouldBe false + + // And the gate lifts with the settled state — deferred, not cancelled. + val bystanderZip = File(externalLogsDir, "${bystander.name}.zip") + withTimeout(AWAIT_TIMEOUT_MS) { + while (!bystanderZip.exists()) delay(POLL_MS) + } + zipped.toList() shouldBe listOf(bystander) } } @@ -331,6 +400,31 @@ class RecorderModuleStartFailureTest : BaseTest() { } } + /** + * A zipped session keeps its name as an archive after its directory is gone, and a zip still + * being written keeps it as a '.zip.tmp'. The session ID is derived from that name, so a retry + * within the same second that reused it would hand a live recording the identity of an archive + * that already exists — and whatever the user then shares is the wrong one. + */ + @Test + fun `a session name left behind by an archive is not reused`() { + withModules(timeSource = TestTimeSource(elapsedRealtimeMs = 100_000L)) { modules -> + val module = modules.create() + + val first = module.startRecorder() + module.stopRecorder() shouldBe first + + first.deleteRecursively() shouldBe true + File(externalLogsDir, "${first.name}.zip").writeText("archived") + File(externalLogsDir, "${first.name}_2.zip.tmp").writeText("half an archive") + + val second = module.startRecorder() + second.name shouldBe "${first.name}_3" + second.exists() shouldBe true + DebugSessionManager.deriveSessionId(second) shouldNotBe DebugSessionManager.deriveSessionId(first) + } + } + /** * 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 @@ -397,5 +491,10 @@ class RecorderModuleStartFailureTest : BaseTest() { // 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 + + // Waiting for something a live collector has to do. Bounded so a regression reports the + // step that never happened instead of burning the whole block envelope. + private const val AWAIT_TIMEOUT_MS = 5_000L + private const val POLL_MS = 25L } }