diff --git a/app/src/gplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplay.kt b/app/src/gplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplay.kt index 465ce946..d8c9b32e 100644 --- a/app/src/gplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplay.kt +++ b/app/src/gplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplay.kt @@ -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") } } 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 0da0b06f..3ecdc651 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 @@ -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(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, 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 ed3d6177..6afefebc 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 @@ -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() + private val logCapture = object : Logging.Logger { + override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map?) { + 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(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() @@ -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() + 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() + coEvery { diagnostics.debugInfo() } returns null + + withRealtimeModule(diagnostics) { module -> + module.startRecorder() + + module.state.first().isRecording shouldBe true + logLines.any { it.startsWith("Upgrade diagnostics") } shouldBe false + } + } } diff --git a/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplayTest.kt b/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplayTest.kt index 0c8d86ce..ed95f3fe 100644 --- a/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplayTest.kt +++ b/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/UpgradeDiagnosticsGplayTest.kt @@ -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().apply { + coEvery { snapshot() } returns BillingCache.Snapshot( + lastProStateAt = 0L, + lastProStateSku = "", + proUnconfirmedSince = 0L, + ) + }, + curriculumVitae = mockk().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(