diff --git a/app/src/gplay/java/eu/darken/capod/common/upgrade/core/BillingCache.kt b/app/src/gplay/java/eu/darken/capod/common/upgrade/core/BillingCache.kt index fc8f0e47..f35d5cec 100644 --- a/app/src/gplay/java/eu/darken/capod/common/upgrade/core/BillingCache.kt +++ b/app/src/gplay/java/eu/darken/capod/common/upgrade/core/BillingCache.kt @@ -12,24 +12,32 @@ import dagger.hilt.android.qualifiers.ApplicationContext import eu.darken.capod.common.datastore.basicReader import eu.darken.capod.common.datastore.basicWriter import eu.darken.capod.common.datastore.createValue +import eu.darken.capod.common.debug.logging.Logging.Priority.WARN +import eu.darken.capod.common.debug.logging.log +import eu.darken.capod.common.debug.logging.logTag import kotlinx.coroutines.flow.first +import kotlinx.coroutines.withTimeoutOrNull +import java.io.IOException import javax.inject.Inject import javax.inject.Singleton +// Retained legacy migration: installs that predate the DataStore move still carry their upgrade +// state in the "settings_gplay" SharedPreferences file. +private val Context.billingCacheDataStore by preferencesDataStore( + name = "settings_gplay", + produceMigrations = { ctx -> listOf(SharedPreferencesMigration(ctx, "settings_gplay")) }, +) + @Singleton -class BillingCache @Inject constructor( - @ApplicationContext private val context: Context, +class BillingCache internal constructor( + private val dataStore: DataStore, ) { - // Retained legacy migration: installs that predate the DataStore move still carry their upgrade - // state in the "settings_gplay" SharedPreferences file. - private val Context.dataStore by preferencesDataStore( - name = "settings_gplay", - produceMigrations = { ctx -> listOf(SharedPreferencesMigration(ctx, "settings_gplay")) }, - ) + @Inject constructor(@ApplicationContext context: Context) : this(context.billingCacheDataStore) - private val dataStore: DataStore - get() = context.dataStore + // Test seam: the bounded reads/writes below run on real dispatchers, so a virtual-time test + // cannot advance the production bound. Same pattern as UpgradeRepoGplay.launchTimeoutMs. + internal var cacheTimeoutMs: Long = CACHE_TIMEOUT_MS // Raw keys shared between the DataStoreValues and stampLastProState's transaction — one // source of truth for key name and encoding. @@ -66,8 +74,15 @@ class BillingCache @Inject constructor( val proUnconfirmedSince: Long, ) + // Bounded on purpose: a wedged DataStore file lock would otherwise hang the caller forever. + // A timeout must NOT fall back to the default snapshot -- that would report "never bought" + // for an install whose evidence merely couldn't be read, which is the exact distinction the + // debug-log header exists to make. suspend fun snapshot(): Snapshot { - val prefs = dataStore.data.first() + val prefs = withTimeoutOrNull(cacheTimeoutMs) { dataStore.data.first() } ?: run { + log(TAG, WARN) { "snapshot() timed out after ${cacheTimeoutMs}ms" } + throw IOException("BillingCache snapshot timed out after ${cacheTimeoutMs}ms") + } return Snapshot( lastProStateAt = prefs[lastProStateAtKey] ?: 0L, lastProStateSku = prefs[lastProStateSkuKey] ?: "", @@ -83,11 +98,19 @@ class BillingCache @Inject constructor( // entitlement layer out of order) opened a still-valid episode that this older confirmation must // not erase. suspend fun stampLastProState(skuId: String, at: Long) { - dataStore.edit { prefs -> - prefs[lastProStateSkuKey] = skuId - prefs[lastProStateAtKey] = at - val episodeStart = prefs[proUnconfirmedSinceKey] ?: 0L - if (episodeStart in 1..at) prefs[proUnconfirmedSinceKey] = 0L - } + // Fail-soft: this decorates the entitlement path, it must never be the thing that blocks it. + withTimeoutOrNull(cacheTimeoutMs) { + dataStore.edit { prefs -> + prefs[lastProStateSkuKey] = skuId + prefs[lastProStateAtKey] = at + val episodeStart = prefs[proUnconfirmedSinceKey] ?: 0L + if (episodeStart in 1..at) prefs[proUnconfirmedSinceKey] = 0L + } + } ?: log(TAG, WARN) { "stampLastProState($skuId, $at) timed out after ${cacheTimeoutMs}ms, write skipped" } + } + + companion object { + private const val CACHE_TIMEOUT_MS = 2_000L + private val TAG = logTag("Upgrade", "Gplay", "BillingCache") } } 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 c8cb3478..465ce946 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 @@ -1,31 +1,63 @@ package eu.darken.capod.common.upgrade.core +import eu.darken.capod.common.debug.logging.Logging.Priority.WARN +import eu.darken.capod.common.debug.logging.asLog +import eu.darken.capod.common.debug.logging.log +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 java.time.Instant import javax.inject.Inject import javax.inject.Singleton /** - * Reports the local billing cache into the debug log header. + * Reports the local billing cache and the lifetime Pro-state history into the debug log header. * * `lastProStateAt > 0` is the "this install once confirmed a real Pro purchase" bit. It predates * the CurriculumVitae pro-state counters by years and lives in a DataStore that was never migrated * or renamed, so it survives update chains that the newer counters can't speak to. Without it in * the header, a purchase complaint can't be told apart from a never-bought install. * - * Depends on [BillingCache] alone -- see [UpgradeDiagnostics] for why this must not pull in - * UpgradeRepoGplay. + * Depends on [BillingCache] and [CurriculumVitae] alone -- see [UpgradeDiagnostics] for why this + * must not pull in UpgradeRepoGplay. */ @Singleton class UpgradeDiagnosticsGplay @Inject constructor( private val billingCache: BillingCache, + private val curriculumVitae: CurriculumVitae, ) : UpgradeDiagnostics { override suspend fun debugInfo(): String { - val snapshot = billingCache.snapshot() - val lastProAt = snapshot.lastProStateAt.takeIf { it > 0 }?.let { Instant.ofEpochMilli(it) } ?: "never" - val lastProSku = snapshot.lastProStateSku.takeIf { it.isNotEmpty() } ?: "unknown/legacy" - val unconfirmedSince = snapshot.proUnconfirmedSince.takeIf { it > 0 }?.let { Instant.ofEpochMilli(it) } ?: "none" - return "BillingCache(lastProStateAt=$lastProAt, lastProStateSku=$lastProSku, proUnconfirmedSince=$unconfirmedSince)" + val cache = try { + val snapshot = billingCache.snapshot() + val lastProAt = snapshot.lastProStateAt.takeIf { it > 0 }?.let { Instant.ofEpochMilli(it) } ?: "never" + val lastProSku = snapshot.lastProStateSku.takeIf { it.isNotEmpty() } ?: "unknown/legacy" + val unconfirmedSince = + snapshot.proUnconfirmedSince.takeIf { it > 0 }?.let { Instant.ofEpochMilli(it) } ?: "none" + "BillingCache(lastProStateAt=$lastProAt, lastProStateSku=$lastProSku, " + + "proUnconfirmedSince=$unconfirmedSince)" + } catch (e: CancellationException) { + throw e + } catch (e: Exception) { + log(TAG, WARN) { "Billing cache unavailable: ${e.asLog()}" } + "BillingCache=unavailable" + } + // Separate boundary from the cache read above on purpose: these are different DataStores, + // 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() + } catch (e: CancellationException) { + throw e + } catch (e: Exception) { + log(TAG, WARN) { "Pro history unavailable: ${e.asLog()}" } + "unavailable" + } + return "$cache, ProHistory=$history" + } + + companion object { + 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 ab0188f2..0da0b06f 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 @@ -20,15 +20,16 @@ import eu.darken.capod.common.debug.logging.logTag import eu.darken.capod.common.debug.logging.asLog import eu.darken.capod.common.flow.DynamicStateFlow import eu.darken.capod.common.upgrade.UpgradeDiagnostics -import eu.darken.capod.main.core.CurriculumVitae import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.NonCancellable 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.withContext import java.io.File import javax.inject.Inject import javax.inject.Singleton @@ -40,7 +41,6 @@ class RecorderModule @Inject constructor( private val dispatcherProvider: DispatcherProvider, private val installId: InstallId, private val timeSource: TimeSource, - private val curriculumVitae: CurriculumVitae, private val upgradeDiagnostics: UpgradeDiagnostics, ) { @@ -86,46 +86,38 @@ class RecorderModule @Inject constructor( val newRecorder = Recorder(timeSource) newRecorder.start(logFile) - if (!isResume) { - val startTime = timeSource.currentTimeMillis() - writeTriggerFile(sessionDir, startTime) - // The recorder is already live but not yet committed to the state: a - // cancellation escaping the header would abandon it where stopRecorder() - // can't reach it. - try { - logRecordingHeader() - } catch (e: CancellationException) { - newRecorder.stop() - this@RecorderModule.currentLogDir = null - throw e - } - - this@RecorderModule.currentLogDir = sessionDir - - copy( - recorder = newRecorder, - currentLogDir = sessionDir, - recordingStartedAt = startTime, - persistedLogDir = null, - ) - } else { - try { - logRecordingHeader() - } catch (e: CancellationException) { - newRecorder.stop() - this@RecorderModule.currentLogDir = null - throw e - } - - this@RecorderModule.currentLogDir = sessionDir - - copy( - recorder = newRecorder, - currentLogDir = sessionDir, - recordingStartedAt = if (recordingStartedAt > 0L) recordingStartedAt else timeSource.currentTimeMillis(), - persistedLogDir = null, - ) + val startTime = when { + !isResume -> timeSource.currentTimeMillis() + recordingStartedAt > 0L -> recordingStartedAt + else -> timeSource.currentTimeMillis() } + + try { + if (!isResume) writeTriggerFile(sessionDir, startTime) + + logRecordingHeader() + } 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. + withContext(NonCancellable) { + try { + newRecorder.stop() + } catch (stopError: Exception) { + e.addSuppressed(stopError) + } + this@RecorderModule.currentLogDir = null + } + throw e + } + + this@RecorderModule.currentLogDir = sessionDir + + copy( + recorder = newRecorder, + currentLogDir = sessionDir, + recordingStartedAt = startTime, + persistedLogDir = null, + ) } else if (!shouldRecord && isRecording) { requireNotNull(recorder) { "Recorder is null despite isRecording" }.stop() @@ -160,20 +152,7 @@ class RecorderModule @Inject constructor( log(TAG, INFO) { "BuildConfig.Versions: ${BuildConfigWrap.VERSION_DESCRIPTION}" } try { - // Billing complaints usually arrive as debug logs: having the lifetime grace/Pro-loss - // history in the header saves a support round-trip. - log(TAG, INFO) { "Pro history: ${curriculumVitae.proHistory()}" } - } catch (e: CancellationException) { - throw e - } catch (e: Exception) { - // Diagnostics only — a broken history read must not stop the recorder from starting. - log(TAG, WARN) { "Pro history unavailable: ${e.asLog()}" } - } - - // Separate boundary from the block above on purpose: these read different DataStores, and - // the counters above only cover installs new enough to have them. A failure to read one - // must not suppress the other's independent evidence. - try { + // Diagnostics only — a broken read must not stop the recorder from starting. upgradeDiagnostics.debugInfo()?.let { log(TAG, INFO) { "Upgrade diagnostics: $it" } } } catch (e: CancellationException) { throw e 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 0f753377..ed3d6177 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 @@ -1,19 +1,26 @@ package eu.darken.capod.common.debug.recording.core 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.debug.logging.FileLogger import eu.darken.capod.common.debug.logging.Logging import eu.darken.capod.common.upgrade.UpgradeDiagnostics -import eu.darken.capod.main.core.CurriculumVitae import io.kotest.matchers.nulls.shouldBeNull import io.kotest.matchers.nulls.shouldNotBeNull import io.kotest.matchers.shouldBe import io.mockk.coEvery import io.mockk.coVerify +import io.mockk.every import io.mockk.mockk +import io.mockk.mockkObject +import io.mockk.unmockkObject import kotlinx.coroutines.CancellationException +import kotlinx.coroutines.CoroutineExceptionHandler +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.cancel import kotlinx.coroutines.delay import kotlinx.coroutines.flow.first import kotlinx.coroutines.launch @@ -27,18 +34,18 @@ import testhelpers.TestApplication import testhelpers.coroutine.TestDispatcherProvider /** - * The recording header reads two independent diagnostics sources. Both reads happen AFTER the - * recorder is already writing, so a failure in either must never abort the state update — that + * The recording header reads diagnostics that live outside the recorder. Those reads happen AFTER + * the recorder is already writing, so a guarded failure must never abort the state update — that * would leave a running recorder the module no longer knows about, i.e. a debug recording that - * can't be stopped or collected. + * can't be stopped or collected. Failures that DO escape the header have to take the uncommitted + * recorder down with them. */ @RunWith(RobolectricTestRunner::class) @Config(sdk = [33], application = TestApplication::class) class RecorderModuleDiagnosticsTest : BaseTest() { private fun buildModule( - scope: kotlinx.coroutines.CoroutineScope, - curriculumVitae: CurriculumVitae, + scope: CoroutineScope, upgradeDiagnostics: UpgradeDiagnostics, ) = RecorderModule( context = ApplicationProvider.getApplicationContext(), @@ -46,111 +53,15 @@ class RecorderModuleDiagnosticsTest : BaseTest() { dispatcherProvider = TestDispatcherProvider(), installId = mockk(relaxed = true), timeSource = SystemTimeSource, - curriculumVitae = curriculumVitae, upgradeDiagnostics = upgradeDiagnostics, ) - @Test - fun `a failing pro-history read still leaves a tracked recording`() = runTest { - val cv = mockk() - coEvery { cv.proHistory() } throws IllegalStateException("history unreadable") - val diagnostics = mockk() - coEvery { diagnostics.debugInfo() } returns "BillingCache(...)" - - val module = buildModule(backgroundScope, cv, diagnostics) - - module.startRecorder().shouldNotBeNull() - module.state.first { it.isRecording }.currentLogDir.shouldNotBeNull() - // The other source is independent: its evidence must still be collected. - coVerify { diagnostics.debugInfo() } - - module.stopRecorder().shouldNotBeNull() - } - @Test fun `a failing upgrade-diagnostics read still leaves a tracked recording`() = runTest { - val cv = mockk() - coEvery { cv.proHistory() } returns CurriculumVitae.ProHistory( - lastState = null, - graceEngagedCount = 0, - graceEngagedLast = null, - proLostCount = 0, - proLostLast = null, - ) val diagnostics = mockk() coEvery { diagnostics.debugInfo() } throws IllegalStateException("cache unreadable") - val module = buildModule(backgroundScope, cv, diagnostics) - - module.startRecorder().shouldNotBeNull() - module.state.first { it.isRecording }.currentLogDir.shouldNotBeNull() - coVerify { cv.proHistory() } - - module.stopRecorder().shouldNotBeNull() - } - - /** - * Cancellation is the one thing the header reads deliberately rethrow, so it is the one failure - * 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 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. - */ - @Test - fun `a cancelled pro-history read stops the recorder instead of leaking it`() = runTest { - val fileLoggersBefore = Logging.loggers.filterIsInstance() - val cv = mockk() - coEvery { cv.proHistory() } throws CancellationException("scope died mid-read") - val diagnostics = mockk() - coEvery { diagnostics.debugInfo() } returns "BillingCache(...)" - - val module = buildModule(backgroundScope, cv, diagnostics) - - backgroundScope.launch { module.startRecorder() } - delay(1_000) - - coVerify { cv.proHistory() } - module.state.first().isRecording shouldBe false - module.currentLogDir.shouldBeNull() - // The recorder that was already writing when the header aborted got stopped. - Logging.loggers.filterIsInstance() shouldBe fileLoggersBefore - } - - @Test - fun `a cancelled upgrade-diagnostics read stops the recorder instead of leaking it`() = runTest { - val fileLoggersBefore = Logging.loggers.filterIsInstance() - val cv = mockk() - coEvery { cv.proHistory() } returns CurriculumVitae.ProHistory( - lastState = null, - graceEngagedCount = 0, - graceEngagedLast = null, - proLostCount = 0, - proLostLast = null, - ) - val diagnostics = mockk() - coEvery { diagnostics.debugInfo() } throws CancellationException("scope died mid-read") - - val module = buildModule(backgroundScope, cv, diagnostics) - - backgroundScope.launch { module.startRecorder() } - delay(1_000) - - coVerify { diagnostics.debugInfo() } - module.state.first().isRecording shouldBe false - module.currentLogDir.shouldBeNull() - Logging.loggers.filterIsInstance() shouldBe fileLoggersBefore - } - - @Test - fun `both reads failing still leaves a tracked recording`() = runTest { - val cv = mockk() - coEvery { cv.proHistory() } throws IllegalStateException("history unreadable") - val diagnostics = mockk() - coEvery { diagnostics.debugInfo() } throws IllegalStateException("cache unreadable") - - val module = buildModule(backgroundScope, cv, diagnostics) + val module = buildModule(backgroundScope, diagnostics) val logDir = module.startRecorder() logDir.exists() shouldBe true @@ -158,4 +69,67 @@ class RecorderModuleDiagnosticsTest : BaseTest() { module.stopRecorder().shouldNotBeNull() } + + /** + * 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 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. + */ + @Test + fun `a cancelled upgrade-diagnostics read stops the recorder instead of leaking it`() = runTest { + val fileLoggersBefore = Logging.loggers.filterIsInstance() + val diagnostics = mockk() + coEvery { diagnostics.debugInfo() } throws CancellationException("scope died mid-read") + + val module = buildModule(backgroundScope, diagnostics) + + backgroundScope.launch { module.startRecorder() } + delay(1_000) + + coVerify { diagnostics.debugInfo() } + module.state.first().isRecording shouldBe false + module.currentLogDir.shouldBeNull() + // The recorder that was already writing when the header aborted got stopped: its file + // logger is no longer installed. + Logging.loggers.filterIsInstance() shouldBe fileLoggersBefore + } + + /** + * Same window as above, but for an ordinary failure instead of a cancellation. The header's + * injected sources are individually guarded, so the escape path is one of the unguarded first + * log lines — here the build description read. + */ + @Test + fun `a failing header read stops the uncommitted recorder`() = runTest { + val fileLoggersBefore = Logging.loggers.filterIsInstance() + val diagnostics = mockk() + coEvery { diagnostics.debugInfo() } returns "BillingCache(...)" + + mockkObject(BuildConfigWrap) + every { BuildConfigWrap.VERSION_DESCRIPTION } throws IllegalStateException("build info unreadable") + + // Own scope: the escaping exception fails the collector, which must not fail the test's own + // scope. SupervisorJob keeps the module's state flow alive so it can be inspected after. + val moduleScope = CoroutineScope(coroutineContext + SupervisorJob() + CoroutineExceptionHandler { _, _ -> }) + try { + val module = buildModule(moduleScope, diagnostics) + + moduleScope.launch { module.startRecorder() } + delay(1_000) + + module.state.first().isRecording shouldBe false + module.currentLogDir.shouldBeNull() + // Non-vacuity: without the guard's cleanup the started recorder's file logger would + // still be installed here. + Logging.loggers.filterIsInstance() shouldBe fileLoggersBefore + } finally { + moduleScope.cancel() + unmockkObject(BuildConfigWrap) + } + } } diff --git a/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/BillingCacheTest.kt b/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/BillingCacheTest.kt index 166e34ae..d0e64f67 100644 --- a/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/BillingCacheTest.kt +++ b/app/src/testGplay/java/eu/darken/capod/common/upgrade/core/BillingCacheTest.kt @@ -1,15 +1,25 @@ package eu.darken.capod.common.upgrade.core +import android.content.Context +import androidx.datastore.core.DataStore +import androidx.datastore.preferences.core.Preferences import androidx.test.core.app.ApplicationProvider import eu.darken.capod.common.datastore.value +import io.kotest.assertions.throwables.shouldThrow import io.kotest.matchers.shouldBe +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.awaitCancellation +import kotlinx.coroutines.flow.Flow +import kotlinx.coroutines.flow.flow import kotlinx.coroutines.test.runTest +import kotlinx.coroutines.withContext 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 java.io.IOException @RunWith(RobolectricTestRunner::class) @Config(sdk = [33], application = TestApplication::class) @@ -17,53 +27,90 @@ class BillingCacheTest : BaseTest() { // One test method on purpose: BillingCache is a @Singleton in production, and DataStore // forbids two active instances on the same file — a second BillingCache in this process - // would crash, not exercise anything real. + // would crash, not exercise anything real. That includes the legacy-migration check below. @Test fun `stampLastProState round-trips through the DataStoreValues`() = runTest { - // Real DataStore, no mocks: this catches an encoding mismatch between the raw keys the - // atomic stamp transaction writes and the keys/types the DataStoreValues read. - val cache = BillingCache(ApplicationProvider.getApplicationContext()) + // Real time on purpose: the reads/writes below are bounded by cacheTimeoutMs, and the real + // DataStore does its I/O off the test scheduler -- under virtual time the bound would fire + // instantly while nothing else is scheduled. + withContext(Dispatchers.IO) { + val context = ApplicationProvider.getApplicationContext() - cache.lastProStateAt.value() shouldBe 0L - cache.lastProStateSku.value() shouldBe "" + // Installs that predate the DataStore move keep their upgrade state in the legacy + // "settings_gplay" SharedPreferences file. Seeded BEFORE the first DataStore access: + // dropping the migration would silently downgrade such an install to "never bought". + context.getSharedPreferences("settings_gplay", Context.MODE_PRIVATE).edit() + .putLong("gplay.cache.lastProAt", 1_000L) + .putString("gplay.cache.lastProSku", "legacy.sku") + .putLong("gplay.cache.proUnconfirmedAt", 2_000L) + .commit() - // Defaults on a never-Pro install: this exact triple is what the debug-log header reports - // as "never / unknown-legacy / none", and it's the signal that separates a never-bought - // install from one whose entitlement went missing. - cache.snapshot() shouldBe BillingCache.Snapshot( - lastProStateAt = 0L, - lastProStateSku = "", - proUnconfirmedSince = 0L, - ) + // Real DataStore, no mocks: this catches an encoding mismatch between the raw keys the + // atomic stamp transaction writes and the keys/types the DataStoreValues read. + val cache = BillingCache(context) + cache.lastProStateAt.value() shouldBe 1_000L + cache.lastProStateSku.value() shouldBe "legacy.sku" + + // The migrated triple has to surface through snapshot() too -- that is what the + // debug-log header reads, and it is the signal that separates a never-bought install + // from one whose entitlement went missing. + cache.snapshot() shouldBe BillingCache.Snapshot( + lastProStateAt = 1_000L, + lastProStateSku = "legacy.sku", + proUnconfirmedSince = 2_000L, + ) + + cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 1234L) + + cache.lastProStateAt.value() shouldBe 1234L + cache.lastProStateSku.value() shouldBe OurSku.Iap.PRO_UPGRADE.id + + cache.stampLastProState(OurSku.Sub.PRO_UPGRADE.id, 5678L) + + cache.lastProStateAt.value() shouldBe 5678L + cache.lastProStateSku.value() shouldBe OurSku.Sub.PRO_UPGRADE.id + + // Occurrence-aware episode clear: a confirmation closes an episode that began at or before + // it, but must leave a NEWER episode intact — a connection failure that occurred after this + // confirmation but was processed out of order opened a still-valid episode. + cache.proUnconfirmedSince.value(4_000L) + cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 5_000L) // confirmation newer than episode + cache.proUnconfirmedSince.value() shouldBe 0L + + cache.proUnconfirmedSince.value(9_000L) + cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 8_000L) // confirmation older than episode + cache.proUnconfirmedSince.value() shouldBe 9_000L + + // snapshot() must agree with the individual reads. It exists so the debug-log header reads + // all three in ONE DataStore emission: three separate reads can straddle a concurrent + // stampLastProState and report a combination that never existed. + cache.snapshot() shouldBe BillingCache.Snapshot( + lastProStateAt = 8_000L, + lastProStateSku = OurSku.Iap.PRO_UPGRADE.id, + proUnconfirmedSince = 9_000L, + ) + } + } + + @Test + fun `a wedged datastore is bounded, reads fail loudly and writes fail soft`() = runTest { + // Fake store, no file: a second real DataStore on the same file would crash this process. + val cache = BillingCache(HangingPreferencesDataStore()).apply { cacheTimeoutMs = 50L } + + // A timeout must not masquerade as a default snapshot -- "never bought" and "couldn't read + // the evidence" are the two things the debug-log header exists to tell apart. + shouldThrow { cache.snapshot() } + + // The write only decorates the entitlement path, it must never block it. cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 1234L) - - cache.lastProStateAt.value() shouldBe 1234L - cache.lastProStateSku.value() shouldBe OurSku.Iap.PRO_UPGRADE.id - - cache.stampLastProState(OurSku.Sub.PRO_UPGRADE.id, 5678L) - - cache.lastProStateAt.value() shouldBe 5678L - cache.lastProStateSku.value() shouldBe OurSku.Sub.PRO_UPGRADE.id - - // Occurrence-aware episode clear: a confirmation closes an episode that began at or before - // it, but must leave a NEWER episode intact — a connection failure that occurred after this - // confirmation but was processed out of order opened a still-valid episode. - cache.proUnconfirmedSince.value(4_000L) - cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 5_000L) // confirmation newer than episode - cache.proUnconfirmedSince.value() shouldBe 0L - - cache.proUnconfirmedSince.value(9_000L) - cache.stampLastProState(OurSku.Iap.PRO_UPGRADE.id, 8_000L) // confirmation older than episode - cache.proUnconfirmedSince.value() shouldBe 9_000L - - // snapshot() must agree with the individual reads. It exists so the debug-log header reads - // all three in ONE DataStore emission: three separate reads can straddle a concurrent - // stampLastProState and report a combination that never existed. - cache.snapshot() shouldBe BillingCache.Snapshot( - lastProStateAt = 8_000L, - lastProStateSku = OurSku.Iap.PRO_UPGRADE.id, - proUnconfirmedSince = 9_000L, - ) } } + +/** DataStore that never answers -- stands in for a wedged file lock. */ +internal class HangingPreferencesDataStore : DataStore { + override val data: Flow = flow { awaitCancellation() } + + override suspend fun updateData(transform: suspend (Preferences) -> Preferences): Preferences = + awaitCancellation() +} 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 25030779..0c8d86ce 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 @@ -1,17 +1,33 @@ package eu.darken.capod.common.upgrade.core +import eu.darken.capod.main.core.CurriculumVitae +import io.kotest.assertions.throwables.shouldThrow import io.kotest.matchers.shouldBe import io.kotest.matchers.string.shouldContain +import io.kotest.matchers.string.shouldNotContain import io.mockk.coEvery import io.mockk.mockk +import kotlinx.coroutines.CancellationException import kotlinx.coroutines.test.runTest import org.junit.jupiter.api.Test import testhelpers.BaseTest class UpgradeDiagnosticsGplayTest : BaseTest() { - private fun create(snapshot: BillingCache.Snapshot) = UpgradeDiagnosticsGplay( - billingCache = mockk().apply { coEvery { this@apply.snapshot() } returns snapshot }, + private val proHistory = CurriculumVitae.ProHistory( + lastState = CurriculumVitae.ProState.PURCHASED, + graceEngagedCount = 2, + graceEngagedLast = null, + proLostCount = 0, + proLostLast = null, + ) + + private fun create( + snapshot: () -> BillingCache.Snapshot, + history: () -> CurriculumVitae.ProHistory = { proHistory }, + ) = UpgradeDiagnosticsGplay( + billingCache = mockk().apply { coEvery { this@apply.snapshot() } answers { snapshot() } }, + curriculumVitae = mockk().apply { coEvery { proHistory() } answers { history() } }, ) @Test @@ -19,20 +35,104 @@ class UpgradeDiagnosticsGplayTest : BaseTest() { // The whole point of this line in the log header is telling "never bought" apart from // "bought once, entitlement now missing". A raw 0 reads as a 1970 timestamp. val info = create( - BillingCache.Snapshot(lastProStateAt = 0L, lastProStateSku = "", proUnconfirmedSince = 0L) + { BillingCache.Snapshot(lastProStateAt = 0L, lastProStateSku = "", proUnconfirmedSince = 0L) } ).debugInfo() - info shouldBe "BillingCache(lastProStateAt=never, lastProStateSku=unknown/legacy, proUnconfirmedSince=none)" + info shouldContain + "BillingCache(lastProStateAt=never, lastProStateSku=unknown/legacy, proUnconfirmedSince=none)" + } + + @Test + fun `the pro history rides along so a complaint arrives with both records`() = runTest { + val info = create( + { BillingCache.Snapshot(lastProStateAt = 0L, lastProStateSku = "", proUnconfirmedSince = 0L) } + ).debugInfo() + + info shouldContain "ProHistory=$proHistory" + } + + @Test + fun `a broken history read still reports the billing cache`() = runTest { + // Different DataStores: one failing must not suppress the other's independent evidence. + val info = create( + snapshot = { + BillingCache.Snapshot( + lastProStateAt = 1_700_000_000_000L, + lastProStateSku = OurSku.Iap.PRO_UPGRADE.id, + proUnconfirmedSince = 0L, + ) + }, + history = { throw IllegalStateException("storage is full") }, + ).debugInfo() + + info shouldContain "lastProStateSku=${OurSku.Iap.PRO_UPGRADE.id}" + info shouldContain "ProHistory=unavailable" + } + + @Test + fun `a broken billing cache read still reports the pro history`() = runTest { + // Mirror image of the above: the billing cache DataStore failing must not suppress the + // lifetime pro-state counters, which live in a different store. + var historyReads = 0 + val info = create( + snapshot = { throw IllegalStateException("datastore is corrupt") }, + history = { historyReads++; proHistory }, + ).debugInfo() + + historyReads shouldBe 1 + info shouldContain "BillingCache=unavailable" + info shouldContain "ProHistory=$proHistory" + } + + @Test + fun `a cancelled billing cache read is not swallowed`() = runTest { + shouldThrow { + create( + snapshot = { throw CancellationException("scope died") }, + ).debugInfo() + } + } + + @Test + fun `a cancelled history read is not swallowed`() = runTest { + // Symmetric to the cache read: cancellation is not a diagnostics failure, it means the + // caller's scope died and the header read must unwind with it. + shouldThrow { + create( + snapshot = { + BillingCache.Snapshot(lastProStateAt = 0L, lastProStateSku = "", proUnconfirmedSince = 0L) + }, + history = { throw CancellationException("scope died") }, + ).debugInfo() + } + } + + @Test + fun `a wedged billing cache is reported as unavailable, not as a never-pro install`() = runTest { + // End-to-end over a real BillingCache whose store never answers: the bounded read throws, + // and the header must say the evidence is missing instead of claiming "never bought". + val diagnostics = UpgradeDiagnosticsGplay( + billingCache = BillingCache(HangingPreferencesDataStore()).apply { cacheTimeoutMs = 50L }, + curriculumVitae = mockk().apply { coEvery { proHistory() } returns proHistory }, + ) + + val info = diagnostics.debugInfo() + + info shouldContain "BillingCache=unavailable" + info shouldNotContain "lastProStateAt=never" + info shouldContain "ProHistory=$proHistory" } @Test fun `a confirmed purchase reports an instant and the sku`() = runTest { val info = create( - BillingCache.Snapshot( - lastProStateAt = 1_700_000_000_000L, - lastProStateSku = OurSku.Iap.PRO_UPGRADE.id, - proUnconfirmedSince = 0L, - ) + { + BillingCache.Snapshot( + lastProStateAt = 1_700_000_000_000L, + lastProStateSku = OurSku.Iap.PRO_UPGRADE.id, + proUnconfirmedSince = 0L, + ) + } ).debugInfo() info shouldContain "lastProStateAt=2023-11-14T22:13:20Z" @@ -43,11 +143,13 @@ class UpgradeDiagnosticsGplayTest : BaseTest() { @Test fun `an open unconfirmed episode is reported as an instant`() = runTest { val info = create( - BillingCache.Snapshot( - lastProStateAt = 1_700_000_000_000L, - lastProStateSku = OurSku.Sub.PRO_UPGRADE.id, - proUnconfirmedSince = 1_700_000_500_000L, - ) + { + BillingCache.Snapshot( + lastProStateAt = 1_700_000_000_000L, + lastProStateSku = OurSku.Sub.PRO_UPGRADE.id, + proUnconfirmedSince = 1_700_000_500_000L, + ) + } ).debugInfo() info shouldContain "proUnconfirmedSince=2023-11-14T22:21:40Z"