fix(debug): Keep the recorder usable when a recording fails to start

Starting a recording spans several steps — create the session directory,
start the recorder, persist the trigger file, write the header — and only
the last of them commits the recorder into the module's state. Anything
throwing inside that window escaped the reactive collector, which then
died for the rest of the process: the started recorder kept writing where
nothing could stop it, the trigger file survived to re-attempt the dead
session on every launch, and startRecorder() waited forever for a state
nobody would publish. The debug log toggle stayed dead until reinstall.

The whole start branch is now guarded. A failure rolls back first — stop
the recorder, clear the log dir mirror, remove the trigger file, delete a
session dir this attempt created — and only then decides what the failure
means: our own scope dying still takes the collector with it, anything
else (a cancellation from inside the start work included) is committed as
a start failure and surfaced to the caller. shouldRecord is reset with it,
so the every-state collector lands in the idle branch instead of retrying.

The stop branch gets the same treatment: a recorder that cannot stop is
logged and the cleared state committed anyway, so an awaiting stop
completes. Recorder.stop() itself now guarantees logger removal, writer
closure and reference clearing. Session directory names get a collision
suffix, since a same-second retry would otherwise share a directory with
the attempt it replaces, and the public start/stop entry points are
serialized so two callers cannot race the same transition.
This commit is contained in:
darken
2026-08-04 18:26:47 +02:00
committed by Matthias Urhahn
parent e7ee126f7e
commit f9327930b5
5 changed files with 587 additions and 68 deletions
@@ -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
}
}
}
@@ -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<T>(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
@@ -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<RecorderModule.RecordingStartFailedException> { module.startRecorder() }
coVerify { diagnostics.debugInfo() }
module.state.first().isRecording shouldBe false
@@ -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<RecorderModule>()
fun create(recorderFactory: (() -> Recorder)? = null): RecorderModule = RecorderModule(
context = ApplicationProvider.getApplicationContext(),
appScope = scope,
dispatcherProvider = TestDispatcherProvider(Dispatchers.IO),
installId = mockk<InstallId>(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<UpgradeDiagnostics>().apply {
coEvery { debugInfo() } returns null
},
block: suspend (Modules) -> Unit,
) {
val moduleScope = CoroutineScope(Dispatchers.IO + SupervisorJob())
val fileLoggersBefore = Logging.loggers.filterIsInstance<FileLogger>()
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<FileLogger>() - fileLoggersBefore.toSet()
leaked.forEach { Logging.remove(it) }
leaked shouldBe emptyList<FileLogger>()
}
}
// 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<IllegalStateException> { 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<IllegalStateException> { 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<Throwable?>(CancellationException("bounded read gave up"))
val diagnostics = mockk<UpgradeDiagnostics>()
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<RecorderModule.RecordingStartFailedException> { 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<IllegalStateException> { 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<IllegalStateException> { 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<IllegalStateException> { 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<DebugSession.Recording>()
}
}
@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<Recorder>(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
}
}
@@ -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
}
}
}