TySS-Dev/capod
1
0
Fork 0
mirror of https://github.com/d4rken-org/capod.git synced 2026-09-14 18:26:11 -04:00
Code Issues Packages Projects Releases Wiki Activity

fix(debug): Make the recorder the only writer of the debug flag

Browse Source 
The module's flag collector was pure redundancy: State.recorder is only
ever written right after a Recorder.start()/stop() that already published
the same value. Its one added behaviour was a hazard - a late-delivered
committed stop could overwrite the flag a newer session's start() had just
set, blanking diagnostics for up to the five seconds the header read is
bounded at.

Recorder.start()/stop() stay the single writers, next to the file logger
they install.

The collector's test goes with it: it hard-coded a two-collector queue
depth that can no longer be reached. In its place, a test asserting the
flag against the recorder itself, and one that forces the late-stop
delivery through a hand-stepped app-scope dispatcher.

Fixes review findings F2, F3, F4
This commit is contained in:
darken
2026-09-01 10:11:01 +02:00
committed by Matthias Urhahn
parent cec36268e0
commit 3662904d75
3 changed files with 186 additions and 73 deletions
Download Patch File Download Diff File Expand all files Collapse all files
app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt
-14
View File
@@ -11,7 +11,6 @@ import eu.darken.capod.common.SystemTimeSource
import eu.darken.capod.common.TimeSource
import eu.darken.capod.common.coroutine.AppScope
import eu.darken.capod.common.coroutine.DispatcherProvider
import eu.darken.capod.common.debug.Bugs
import eu.darken.capod.common.debug.logging.Logging.Priority.ERROR
import eu.darken.capod.common.debug.logging.Logging.Priority.INFO
import eu.darken.capod.common.debug.logging.Logging.Priority.WARN
@@ -26,8 +25,6 @@ import kotlinx.coroutines.NonCancellable
import kotlinx.coroutines.currentCoroutineContext
import kotlinx.coroutines.ensureActive
import kotlinx.coroutines.flow.Flow
import kotlinx.coroutines.flow.distinctUntilChangedBy
import kotlinx.coroutines.flow.drop
import kotlinx.coroutines.flow.filter
import kotlinx.coroutines.flow.first
import kotlinx.coroutines.flow.launchIn
@@ -208,17 +205,6 @@ class RecorderModule @Inject constructor(
}
}
.launchIn(appScope)
// Confirms the flag on committed transitions only. Requests carry an `isRecording` the
// recorder has already moved past, so publishing one would overwrite the flip that
// [Recorder.start]/[Recorder.stop] did next to the file logger they actually installed.
// The pre-start emissions collapse into one, which is then dropped; swapping the two
// operators lets the start request through again.
internalState.flow
.distinctUntilChangedBy { it.isRecording }
.drop(1)
.onEach { Bugs.isDebug.value = it.isRecording }
.launchIn(appScope)
}
// Header lines written into a freshly started recording. Runs AFTER the recorder is live, so
app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderDebugFlagTest.kt
+105
View File
@@ -0,0 +1,105 @@
package eu.darken.capod.common.debug.recording.core
import android.content.Context
import androidx.test.core.app.ApplicationProvider
import eu.darken.capod.common.debug.Bugs
import eu.darken.capod.common.debug.logging.FileLogger
import eu.darken.capod.common.debug.logging.Logging
import io.kotest.assertions.throwables.shouldThrow
import io.kotest.assertions.withClue
import io.kotest.matchers.shouldBe
import io.mockk.every
import io.mockk.mockkObject
import io.mockk.unmockkObject
import kotlinx.coroutines.runBlocking
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 java.io.File
import java.io.IOException
/**
* [Recorder] is the writer of [Bugs.isDebug] that sits next to the file logger it installs, so it
* is the only one that can flip the flag in the same breath as the recording it describes. Asserted
* against the recorder itself and nothing else: a test that goes through [RecorderModule] is
* satisfied by the module's own flag collector, and would keep passing if the recorder stopped
* writing the flag entirely.
*/
@RunWith(RobolectricTestRunner::class)
@Config(sdk = [33], application = TestApplication::class)
class RecorderDebugFlagTest : BaseTest() {
private val context: Context
get() = ApplicationProvider.getApplicationContext()
private val logDir: File
get() = File(context.cacheDir, "recorder-flag-test")
private lateinit var recorder: Recorder
@Before
fun setup() {
logDir.deleteRecursively()
logDir.mkdirs()
recorder = Recorder(TestTimeSource())
}
@After
fun teardown() {
unmockkObject(Logging)
runBlocking { runCatching { recorder.stop() } }
Logging.loggers.filterIsInstance<FileLogger>().forEach { Logging.remove(it) }
logDir.deleteRecursively()
Bugs.isDebug.value = false
}
@Test
fun `start publishes the debug flag before it returns`() = runBlocking {
Bugs.isDebug.value shouldBe false
recorder.start(File(logDir, "core.log"))
withClue("a recording is live the moment start() returns, so the flag has to read true") {
Bugs.isDebug.value shouldBe true
}
}
@Test
fun `stop clears the debug flag`() = runBlocking {
recorder.start(File(logDir, "core.log"))
withClue("the flag has to be set before this test can say anything about clearing it") {
Bugs.isDebug.value shouldBe true
}
recorder.stop()
withClue("no recording is live any more, so the flag has to read false") {
Bugs.isDebug.value shouldBe false
}
}
@Test
fun `stop clears the debug flag even when the teardown fails`() = runBlocking {
recorder.start(File(logDir, "core.log"))
withClue("the flag has to be set before this test can say anything about clearing it") {
Bugs.isDebug.value shouldBe true
}
// Uninstalling the logger is the first thing stop() does and the only part of it that can
// throw: FileLogger.stop() swallows its own IO failures.
mockkObject(Logging)
every { Logging.remove(any()) } throws IOException("Uninstall failed")
shouldThrow<IOException> { recorder.stop() }
withClue("the recorder is no longer recording, failed teardown or not") {
Bugs.isDebug.value shouldBe false
}
}
}
app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleDebugFlagTest.kt → app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStaleStopFlagTest.kt
+81 -59
View File
@@ -9,6 +9,7 @@ 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.withClue
import io.kotest.matchers.ints.shouldBeGreaterThanOrEqual
import io.kotest.matchers.shouldBe
import io.mockk.coEvery
import io.mockk.mockk
@@ -19,7 +20,6 @@ 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
@@ -40,24 +40,23 @@ import java.util.concurrent.TimeUnit
import kotlin.coroutines.CoroutineContext
/**
* [Bugs.isDebug] has two writers: [Recorder.start]/[Recorder.stop] flip it around the file logger
* they install, and a collector in [RecorderModule]'s init mirrors `isRecording` from every state
* emission. Three of those emissions carry an `isRecording` the recorder has already moved past —
* a start request is published while `recorder` is still null, a stop request while it is still
* set — so the collector can publish a value that contradicts the logger that is actually running.
* The flag collector in [RecorderModule]'s init mirrors `isRecording` from the module state, and a
* committed stop is a value it legitimately publishes. Delivery of that value is not tied to the
* recording it describes: the collector runs on the app scope while the recorder work runs on the
* producer's IO context, so the `false` can land after the next session's [Recorder.start] has
* already written `true`. `distinctUntilChangedBy`/`drop(1)` do not filter it — a genuine stop and
* a genuine start are distinct values, and both pass.
*
* The start request is the expensive one: the state that would repair it only commits after the
* recording header has been read, which is bounded at five seconds. Everything logged in that
* window loses the debug-only diagnostics that key off this flag.
* The window that follows is not short: the state that would repair the flag only commits after
* `logRecordingHeader()`, which is bounded at five seconds.
*
* The two writers run on the same scope but different dispatchers, so which one lands last is a
* race. It is forced here rather than waited for: the module's scope gets a dispatcher whose queue
* this test steps through by hand, which is what a saturated Dispatchers.Default does to the flag
* collector's continuation while the start work proceeds on an IO thread.
* Forced rather than waited for: the module's app scope gets a dispatcher whose queue this test
* steps through by hand, which is what a saturated Dispatchers.Default does to the flag collector's
* continuation while the module's own producer proceeds on IO.
*/
@RunWith(RobolectricTestRunner::class)
@Config(sdk = [33], application = TestApplication::class)
class RecorderModuleDebugFlagTest : BaseTest() {
class RecorderModuleStaleStopFlagTest : BaseTest() {
private val context: Context
get() = ApplicationProvider.getApplicationContext()
@@ -68,16 +67,22 @@ class RecorderModuleDebugFlagTest : BaseTest() {
private val externalLogsDir: File
get() = File(context.getExternalFilesDir(null), "debug/logs")
private val secondSessionDir: File
get() = File(context.cacheDir, "stale-stop-second-session")
@Before
fun cleanRecorderFiles() {
triggerFile.delete()
externalLogsDir.deleteRecursively()
File(context.cacheDir, "debug/logs").deleteRecursively()
secondSessionDir.deleteRecursively()
secondSessionDir.mkdirs()
}
@After
fun resetDebugFlag() {
Logging.loggers.filterIsInstance<FileLogger>().forEach { Logging.remove(it) }
secondSessionDir.deleteRecursively()
Bugs.isDebug.value = false
}
@@ -132,24 +137,11 @@ class RecorderModuleDebugFlagTest : BaseTest() {
}
@Test
fun `the flag collector does not clobber the flag of a recorder that is already live`() {
fun `a late committed stop does not clear the flag of the session that replaced it`() {
val moduleDispatcher = SteppingDispatcher()
val moduleScope = CoroutineScope(moduleDispatcher + SupervisorJob())
val callerScope = CoroutineScope(Dispatchers.IO + SupervisorJob())
// Mirrors the real recorder: the flag is flipped where the file logger is installed, and
// parked there so the module cannot commit the state that would paper over a stale write.
val recorderLive = CountDownLatch(1)
val releaseStart = CountDownLatch(1)
val recorder = mockk<Recorder>(relaxed = true)
coEvery { recorder.start(any()) } coAnswers {
Bugs.isDebug.value = true
recorderLive.countDown()
releaseStart.await(AWAIT_TIMEOUT_MS, TimeUnit.MILLISECONDS)
Unit
}
coEvery { recorder.stop() } coAnswers { Bugs.isDebug.value = false }
val module = RecorderModule(
context = context,
appScope = moduleScope,
@@ -157,52 +149,63 @@ class RecorderModuleDebugFlagTest : BaseTest() {
installId = mockk<InstallId>(relaxed = true),
timeSource = SystemTimeSource,
upgradeDiagnostics = mockk<UpgradeDiagnostics>().apply { coEvery { debugInfo() } returns null },
).apply { recorderFactory = { recorder } }
)
// Stands in for the recorder of the session that follows. In production this is the module's
// own next recorder: its start() runs on the producer's IO context, not on the app scope
// whose queue is held below, so it can write the flag while the collector still owes a value.
val nextSession = Recorder(SystemTimeSource)
try {
// Both init collectors have subscribed and consumed the initial state.
moduleDispatcher.barrier(AWAIT_TIMEOUT_MS) shouldBe true
runBlocking { withTimeout(AWAIT_TIMEOUT_MS) { module.state.first() } }.isRecording shouldBe false
moduleDispatcher.barrier(AWAIT_TIMEOUT_MS) shouldBe true
moduleDispatcher.hold()
val start = callerScope.async { module.startRecorder() }
// The start request has been published: both collectors are queued on it.
runBlocking {
withTimeout(AWAIT_TIMEOUT_MS) {
while (moduleDispatcher.heldCount() < 2) delay(POLL_MS)
}
}
// Step 1: the state machine collector, which hands the start work to the module's own
// producer and leaves the recorder live but uncommitted.
moduleDispatcher.releaseOne(AWAIT_TIMEOUT_MS) shouldBe true
recorderLive.await(AWAIT_TIMEOUT_MS, TimeUnit.MILLISECONDS) shouldBe true
withClue("the recorder's own write is the baseline this test measures against") {
runBlocking { withTimeout(AWAIT_TIMEOUT_MS) { withContext(Dispatchers.IO) { module.startRecorder() } } }
settleAndHold(moduleDispatcher)
withClue("the first recording is live, so the flag is true before anything is held") {
Bugs.isDebug.value shouldBe true
}
// Step 2: the flag collector, still holding the pre-start emission.
withClue("the flag collector's turn on the start request must still be pending") {
val stop = callerScope.async { module.stopRecorder() }
// The stop request has been published and the state machine collector is queued on it.
runBlocking {
withTimeout(AWAIT_TIMEOUT_MS) {
while (moduleDispatcher.heldCount() < 1) delay(POLL_MS)
}
}
// Step 1: the state machine collector. It hands the stop to the module's own producer,
// which stops the recorder on IO and publishes the committed stop.
withClue("the state machine collector's turn on the stop request must be pending") {
moduleDispatcher.releaseOne(AWAIT_TIMEOUT_MS) shouldBe true
}
runBlocking { withTimeout(AWAIT_TIMEOUT_MS) { stop.await() } }
withClue("the recorder stopped itself, so nothing is recording at this point") {
Bugs.isDebug.value shouldBe false
}
// The committed stop is queued for the flag collector and has not been delivered yet.
withClue("the collector must still owe a delivery, or this test proves nothing") {
moduleDispatcher.heldCount() shouldBeGreaterThanOrEqual 1
}
runBlocking { nextSession.start(File(secondSessionDir, "core.log")) }
withClue("the new session's recorder wrote the flag next to the logger it installed") {
Bugs.isDebug.value shouldBe true
}
// Step 2: everything the collector still owes, the committed stop included.
moduleDispatcher.release()
moduleDispatcher.barrier(AWAIT_TIMEOUT_MS) shouldBe true
withClue("a live recorder is writing to the log file, so isDebug must not read false") {
Bugs.isDebug.value shouldBe true
}
releaseStart.countDown()
moduleDispatcher.release()
runBlocking { withTimeout(AWAIT_TIMEOUT_MS) { start.await() } }
} finally {
releaseStart.countDown()
moduleDispatcher.release()
runBlocking {
try {
runCatching { withTimeout(AWAIT_TIMEOUT_MS) { nextSession.stop() } }
runCatching {
withTimeout(AWAIT_TIMEOUT_MS) { withContext(Dispatchers.IO) { module.stopRecorder() } }
} catch (e: Exception) {
// cleanup only
}
}
callerScope.cancel()
@@ -211,8 +214,27 @@ class RecorderModuleDebugFlagTest : BaseTest() {
}
}
/**
* Holds the dispatcher at a point where nothing is queued on it, so the first task released
* afterwards is the first reaction to whatever the test does next.
*/
private fun settleAndHold(dispatcher: SteppingDispatcher) = runBlocking {
withTimeout(AWAIT_TIMEOUT_MS) {
while (true) {
dispatcher.barrier(AWAIT_TIMEOUT_MS) shouldBe true
dispatcher.hold()
dispatcher.barrier(AWAIT_TIMEOUT_MS) shouldBe true
delay(SETTLE_MS)
if (dispatcher.heldCount() == 0) return@withTimeout
dispatcher.release()
delay(SETTLE_MS)
}
}
}
companion object {
private const val AWAIT_TIMEOUT_MS = 5_000L
private const val POLL_MS = 10L
private const val SETTLE_MS = 100L
}
}