fix(debug): Keep debug recording available when diagnostics hang

The debug log header read the flavor's upgrade diagnostics unbounded. A
wedged source (a stuck DataStore file lock, a billing store that never
answers) left the recorder started but never committed, so the user asking
for a log got nothing at exactly the moment the app was misbehaving.

The read now runs under a deadline: a source that hangs or fails degrades
to "unavailable" and the recording starts. Completion is tracked
separately from the value, so a flavor that legitimately has nothing to
report (FOSS) still logs no line at all instead of claiming a failure.
Cancellation is unchanged: an outer scope death still rolls the
uncommitted recorder back.

The GPlay diagnostics' pro-history read gets the same bound its billing
cache read already had.
This commit is contained in:
darken
2026-08-02 12:40:32 +02:00
committed by Matthias Urhahn
parent 72fb1d3b17
commit 6b2536c74f
4 changed files with 152 additions and 4 deletions
@@ -7,6 +7,7 @@ import eu.darken.capod.common.debug.logging.logTag
import eu.darken.capod.common.upgrade.UpgradeDiagnostics
import eu.darken.capod.main.core.CurriculumVitae
import kotlinx.coroutines.CancellationException
import kotlinx.coroutines.withTimeoutOrNull
import java.time.Instant
import javax.inject.Inject
import javax.inject.Singleton
@@ -28,6 +29,10 @@ class UpgradeDiagnosticsGplay @Inject constructor(
private val curriculumVitae: CurriculumVitae,
) : UpgradeDiagnostics {
// Test seam: the bounded read below runs on real dispatchers, so a virtual-time test cannot
// advance the production bound. Same pattern as BillingCache.cacheTimeoutMs.
internal var historyTimeoutMs: Long = HISTORY_TIMEOUT_MS
override suspend fun debugInfo(): String {
val cache = try {
val snapshot = billingCache.snapshot()
@@ -47,7 +52,12 @@ class UpgradeDiagnosticsGplay @Inject constructor(
// and the counters only cover installs new enough to have them. A failure to read one must
// not suppress the other's independent evidence.
val history = try {
curriculumVitae.proHistory().toString()
// Bounded like the cache read above: a wedged DataStore file lock would otherwise hold
// the debug-log header - and with it the start of the recording - forever.
withTimeoutOrNull(historyTimeoutMs) { curriculumVitae.proHistory().toString() } ?: run {
log(TAG, WARN) { "Pro history timed out after ${historyTimeoutMs}ms" }
"unavailable"
}
} catch (e: CancellationException) {
throw e
} catch (e: Exception) {
@@ -58,6 +68,7 @@ class UpgradeDiagnosticsGplay @Inject constructor(
}
companion object {
private const val HISTORY_TIMEOUT_MS = 2_000L
private val TAG = logTag("Upgrade", "Gplay", "Diagnostics")
}
}
@@ -30,6 +30,7 @@ import kotlinx.coroutines.flow.launchIn
import kotlinx.coroutines.flow.onEach
import kotlinx.coroutines.plus
import kotlinx.coroutines.withContext
import kotlinx.coroutines.withTimeoutOrNull
import java.io.File
import javax.inject.Inject
import javax.inject.Singleton
@@ -44,6 +45,10 @@ class RecorderModule @Inject constructor(
private val upgradeDiagnostics: UpgradeDiagnostics,
) {
// Test seam: the header read below is bounded on real dispatchers, so a virtual-time test cannot
// advance the production bound. Same pattern as BillingCache.cacheTimeoutMs.
internal var headerReadTimeoutMs: Long = HEADER_READ_TIMEOUT_MS
@Volatile
internal var currentLogDir: File? = null
private set
@@ -152,8 +157,19 @@ class RecorderModule @Inject constructor(
log(TAG, INFO) { "BuildConfig.Versions: ${BuildConfigWrap.VERSION_DESCRIPTION}" }
try {
// Diagnostics only — a broken read must not stop the recorder from starting.
upgradeDiagnostics.debugInfo()?.let { log(TAG, INFO) { "Upgrade diagnostics: $it" } }
// Diagnostics only — a broken read must not stop the recorder from starting. Bounded on
// top of that: debug recording is what a user reaches for when the app is ALREADY
// misbehaving, so a source that never answers (a stuck DataStore file lock, a billing
// store that doesn't respond) must not hold up the start of the recording either.
val read = withTimeoutOrNull(headerReadTimeoutMs) { HeaderRead(upgradeDiagnostics.debugInfo()) }
when {
read == null -> log(TAG, WARN) {
"Upgrade diagnostics unavailable, read did not finish within ${headerReadTimeoutMs}ms"
}
// Completion is tracked separately from the value: a flavor that legitimately has
// nothing to report (FOSS) returns null and gets no line at all, not an "unavailable".
read.value != null -> log(TAG, INFO) { "Upgrade diagnostics: ${read.value}" }
}
} catch (e: CancellationException) {
throw e
} catch (e: Exception) {
@@ -161,6 +177,12 @@ class RecorderModule @Inject constructor(
}
}
/**
* Completion marker for a header read: tells a source that legitimately has nothing to report
* (no diagnostics on FOSS) apart from one that never answered within the deadline.
*/
private class HeaderRead<T>(val value: T)
private fun createSessionDir(): File {
val timestamp = timeSource.now().atZone(java.time.ZoneOffset.UTC)
.format(java.time.format.DateTimeFormatter.ofPattern("yyyyMMdd'T'HHmmss'Z'"))
@@ -268,6 +290,9 @@ class RecorderModule @Inject constructor(
private const val FORCE_FILE = "capod_force_debug_run"
private const val MIN_RECORDING_MS = 5_000L
// Budget for the header's diagnostics read.
private const val HEADER_READ_TIMEOUT_MS = 5_000L
@VisibleForTesting
internal fun parseTriggerContent(
content: String,
@@ -4,9 +4,11 @@ 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.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.matchers.longs.shouldBeLessThan
import io.kotest.matchers.nulls.shouldBeNull
import io.kotest.matchers.nulls.shouldNotBeNull
import io.kotest.matchers.shouldBe
@@ -19,12 +21,17 @@ import io.mockk.unmockkObject
import kotlinx.coroutines.CancellationException
import kotlinx.coroutines.CoroutineExceptionHandler
import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.SupervisorJob
import kotlinx.coroutines.awaitCancellation
import kotlinx.coroutines.cancel
import kotlinx.coroutines.delay
import kotlinx.coroutines.flow.first
import kotlinx.coroutines.launch
import kotlinx.coroutines.runBlocking
import kotlinx.coroutines.test.runTest
import org.junit.After
import org.junit.Before
import org.junit.Test
import org.junit.runner.RunWith
import org.robolectric.RobolectricTestRunner
@@ -32,6 +39,8 @@ import org.robolectric.annotation.Config
import testhelpers.BaseTest
import testhelpers.TestApplication
import testhelpers.coroutine.TestDispatcherProvider
import java.util.concurrent.CopyOnWriteArrayList
import kotlin.system.measureTimeMillis
/**
* The recording header reads diagnostics that live outside the recorder. Those reads happen AFTER
@@ -44,18 +53,57 @@ import testhelpers.coroutine.TestDispatcherProvider
@Config(sdk = [33], application = TestApplication::class)
class RecorderModuleDiagnosticsTest : BaseTest() {
private val logLines = CopyOnWriteArrayList<String>()
private val logCapture = object : Logging.Logger {
override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map<String, Any>?) {
logLines.add(message)
}
}
@Before
fun installLogCapture() {
Logging.install(logCapture)
}
@After
fun removeLogCapture() {
Logging.remove(logCapture)
}
private fun buildModule(
scope: CoroutineScope,
upgradeDiagnostics: UpgradeDiagnostics,
dispatcherProvider: DispatcherProvider = TestDispatcherProvider(),
) = RecorderModule(
context = ApplicationProvider.getApplicationContext(),
appScope = scope,
dispatcherProvider = TestDispatcherProvider(),
dispatcherProvider = dispatcherProvider,
installId = mockk<InstallId>(relaxed = true),
timeSource = SystemTimeSource,
upgradeDiagnostics = upgradeDiagnostics,
)
/**
* Real dispatchers on purpose: the header's read deadline is wall-clock, so a virtual-time test
* would skip past it instead of exercising it — an ignored seam has to fail this, not pass after
* the full production budget. The seam is set before [RecorderModule.startRecorder] so no header
* read can run against the production bound.
*/
private fun withRealtimeModule(
upgradeDiagnostics: UpgradeDiagnostics,
headerTimeoutMs: Long = 300L,
block: suspend (RecorderModule) -> Unit,
) {
val moduleScope = CoroutineScope(Dispatchers.IO + SupervisorJob())
try {
val module = buildModule(moduleScope, upgradeDiagnostics, TestDispatcherProvider(Dispatchers.IO))
module.headerReadTimeoutMs = headerTimeoutMs
runBlocking { block(module) }
} finally {
moduleScope.cancel()
}
}
@Test
fun `a failing upgrade-diagnostics read still leaves a tracked recording`() = runTest {
val diagnostics = mockk<UpgradeDiagnostics>()
@@ -132,4 +180,38 @@ class RecorderModuleDiagnosticsTest : BaseTest() {
unmockkObject(BuildConfigWrap)
}
}
/**
* Debug recording is what a user reaches for when the app is ALREADY misbehaving, so a
* diagnostics source that never answers must not be the thing that denies them the log.
*/
@Test
fun `a wedged upgrade diagnostics read does not hold up the recording`() {
val diagnostics = mockk<UpgradeDiagnostics>()
coEvery { diagnostics.debugInfo() } coAnswers { awaitCancellation() }
withRealtimeModule(diagnostics, headerTimeoutMs = 300L) { module ->
val elapsed = measureTimeMillis { module.startRecorder() }
module.state.first().isRecording shouldBe true
logLines.any { it.startsWith("Upgrade diagnostics unavailable") } shouldBe true
// Non-vacuity: without the bound this would sit on the wedged read forever.
elapsed shouldBeLessThan 1_500L
}
}
@Test
fun `a flavor without diagnostics is not reported as unavailable`() {
// FOSS has nothing to report and returns null: no diagnostics line at all, and above all
// not one claiming the read failed or timed out.
val diagnostics = mockk<UpgradeDiagnostics>()
coEvery { diagnostics.debugInfo() } returns null
withRealtimeModule(diagnostics) { module ->
module.startRecorder()
module.state.first().isRecording shouldBe true
logLines.any { it.startsWith("Upgrade diagnostics") } shouldBe false
}
}
}
@@ -8,7 +8,10 @@ import io.kotest.matchers.string.shouldNotContain
import io.mockk.coEvery
import io.mockk.mockk
import kotlinx.coroutines.CancellationException
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.awaitCancellation
import kotlinx.coroutines.test.runTest
import kotlinx.coroutines.withContext
import org.junit.jupiter.api.Test
import testhelpers.BaseTest
@@ -123,6 +126,33 @@ class UpgradeDiagnosticsGplayTest : BaseTest() {
info shouldContain "ProHistory=$proHistory"
}
@Test
fun `a wedged history is reported as unavailable`() = runTest {
// Counterpart to the wedged cache above: a never-answering CurriculumVitae store would hold
// the debug-log header -- and with it the start of the recording -- forever.
// Real time on purpose: under virtual time the bound would fire instantly while nothing else
// is scheduled, so an ignored seam would still pass.
withContext(Dispatchers.IO) {
val diagnostics = UpgradeDiagnosticsGplay(
billingCache = mockk<BillingCache>().apply {
coEvery { snapshot() } returns BillingCache.Snapshot(
lastProStateAt = 0L,
lastProStateSku = "",
proUnconfirmedSince = 0L,
)
},
curriculumVitae = mockk<CurriculumVitae>().apply {
coEvery { proHistory() } coAnswers { awaitCancellation() }
},
).apply { historyTimeoutMs = 50L }
val info = diagnostics.debugInfo()
info shouldContain "BillingCache(lastProStateAt=never"
info shouldContain "ProHistory=unavailable"
}
}
@Test
fun `a confirmed purchase reports an instant and the sku`() = runTest {
val info = create(