Merge main into chore-claudemd-dod-logging

This commit is contained in:
Jason Ross
2026-07-04 23:16:54 -05:00
committed by GitHub
4 changed files with 164 additions and 37 deletions
@@ -3,7 +3,6 @@ package org.libremail.ui.accountsetup
import android.content.ActivityNotFoundException
import android.content.Intent
import android.util.Log
import androidx.lifecycle.ViewModel
import androidx.lifecycle.viewModelScope
import dagger.hilt.android.lifecycle.HiltViewModel
@@ -15,6 +14,7 @@ import kotlinx.coroutines.launch
import org.libremail.auth.OutlookAuthManager
import org.libremail.domain.model.Account
import org.libremail.domain.repository.AccountRepository
import org.libremail.reporting.AppLog
import javax.inject.Inject
/** Stage of an account-setup attempt, shared by the Outlook and manual flows. */
@@ -68,12 +68,18 @@ class AccountSetupViewModel @Inject constructor(
Account.outlook(oauth.email).id
}.fold(
onSuccess = { accountId ->
// No email: the account id embeds it (see accountLogRef) and must never be logged.
AppLog.i(TAG, "Outlook account added")
_state.update { it.copy(status = SetupStatus.DONE, addedAccountId = accountId) }
},
onFailure = { e ->
// Stripped from release builds by the Log.d ProGuard rule (keeps any account
// address / token detail out of shipped logs); visible in debug for diagnosis.
Log.d(TAG, "Outlook sign-in failed after redirect", e)
// AppLog.d's Logcat mirror is stripped from release builds by the -assumenosideeffects
// Log.d ProGuard rule (keeps any account address / token detail out of shipped
// logcat), but that rule only elides the `Log.d(...)` call inside AppLog.d — the
// buffer.record(...) line right after it is untouched, so this breadcrumb still
// reaches a submitted report. The throwable's message may carry the account
// email/token; AppLog's StackTraceScrubber redacts it before it is recorded.
AppLog.d(TAG, "Outlook sign-in failed after redirect", e)
_state.update {
it.copy(status = SetupStatus.IDLE, error = e.message ?: "Microsoft sign-in failed")
}
@@ -5,7 +5,6 @@ import android.content.Context
import android.os.SystemClock
import android.security.keystore.KeyPermanentlyInvalidatedException
import android.security.keystore.UserNotAuthenticatedException
import android.util.Log
import androidx.annotation.VisibleForTesting
import androidx.lifecycle.ViewModel
import androidx.lifecycle.viewModelScope
@@ -32,6 +31,7 @@ import org.libremail.data.security.LockState
import org.libremail.data.security.PassphraseSession
import org.libremail.data.settings.SettingsRepository
import org.libremail.data.sync.SyncScheduler
import org.libremail.reporting.AppLog
import org.libremail.restart.ProcessRestarter
import java.util.concurrent.ExecutionException
import java.util.concurrent.TimeUnit
@@ -149,6 +149,8 @@ class AppLockViewModel @Inject constructor(
keyInvalidated = databaseKeyCipher.isInvalidated(),
)
}
// LockAction is a non-PII enum, so it's safe to record verbatim as a breadcrumb.
AppLog.i(TAG, "app-lock foreground decision: $action")
when (action) {
LockAction.PROCEED -> _uiState.value = AppLockUiState.Unlocked
@@ -191,6 +193,7 @@ class AppLockViewModel @Inject constructor(
viewModelScope.launch {
when (withContext(defaultDispatcher) { unlockOrArm() }) {
UnlockResult.OK -> {
AppLog.i(TAG, "auth seal unlocked; cache readable")
gate.onAuthenticated()
publish()
}
@@ -198,7 +201,7 @@ class AppLockViewModel @Inject constructor(
UnlockResult.UNRECOVERABLE -> {
// The passphrase is permanently unrecoverable (key invalidated or deleted by a
// screen-lock change). Wipe the cache safely at the next cold start and re-sync.
Log.w(TAG, "encrypted cache passphrase unrecoverable; clearing cache")
AppLog.w(TAG, "encrypted cache passphrase unrecoverable; clearing cache")
clearCacheAndRestart(disableAppLock = false)
}
@@ -240,7 +243,7 @@ class AppLockViewModel @Inject constructor(
return runCatching { databaseKeyStore.sealWithAuth() }.fold(
onSuccess = { UnlockResult.OK },
onFailure = { e ->
Log.w(TAG, "arming auth seal failed", e)
AppLog.w(TAG, "arming auth seal failed", e)
UnlockResult.RETRY
},
)
@@ -249,17 +252,17 @@ class AppLockViewModel @Inject constructor(
private suspend fun unwrapSealedPassphrase(): UnlockResult {
// A sealed passphrase exists but its key is gone entirely: it can never be unwrapped.
if (!databaseKeyCipher.hasKey()) {
Log.w(TAG, "auth-sealed passphrase present but key was deleted; cache unrecoverable")
AppLog.w(TAG, "auth-sealed passphrase present but key was deleted; cache unrecoverable")
return UnlockResult.UNRECOVERABLE
}
return try {
databaseKeyStore.unlockWithAuth()
UnlockResult.OK
} catch (e: KeyPermanentlyInvalidatedException) {
Log.w(TAG, "auth-bound key permanently invalidated", e)
AppLog.w(TAG, "auth-bound key permanently invalidated", e)
UnlockResult.UNRECOVERABLE
} catch (e: UserNotAuthenticatedException) {
Log.w(TAG, "auth window elapsed before unwrap; will retry", e)
AppLog.w(TAG, "auth window elapsed before unwrap; will retry", e)
UnlockResult.RETRY
} catch (e: CancellationException) {
throw e
@@ -268,12 +271,13 @@ class AppLockViewModel @Inject constructor(
// process right after a successful auth. Re-lock and let the user retry rather than wiping
// the cache on an ambiguous error (a genuinely lost key still surfaces as UNRECOVERABLE
// via hasKey()/KeyPermanentlyInvalidatedException above).
Log.w(TAG, "unexpected failure unwrapping auth-sealed passphrase; will retry", e)
AppLog.w(TAG, "unexpected failure unwrapping auth-sealed passphrase; will retry", e)
UnlockResult.RETRY
}
}
private suspend fun clearCacheAndRestart(disableAppLock: Boolean) {
AppLog.w(TAG, "clearing encrypted cache and restarting (disableAppLock=$disableAppLock)")
withContext(defaultDispatcher) {
// Record the wipe intent BEFORE flipping app-lock off, so a crash between the two writes
// leaves the wipe still pending (recoverable) rather than a disabled gate over a stale key.
@@ -302,12 +306,12 @@ class AppLockViewModel @Inject constructor(
try {
operation.result.get(SYNC_ENQUEUE_TIMEOUT_SECONDS, TimeUnit.SECONDS)
} catch (e: TimeoutException) {
Log.w(TAG, "re-sync enqueue not confirmed within timeout; restarting anyway", e)
AppLog.w(TAG, "re-sync enqueue not confirmed within timeout; restarting anyway", e)
} catch (e: ExecutionException) {
Log.w(TAG, "re-sync enqueue failed; restarting anyway", e)
AppLog.w(TAG, "re-sync enqueue failed; restarting anyway", e)
} catch (e: InterruptedException) {
Thread.currentThread().interrupt()
Log.w(TAG, "interrupted awaiting re-sync enqueue; restarting anyway", e)
AppLog.w(TAG, "interrupted awaiting re-sync enqueue; restarting anyway", e)
}
}
@@ -23,18 +23,41 @@ import org.junit.Test
import org.libremail.auth.OAuthResult
import org.libremail.auth.OutlookAuthManager
import org.libremail.domain.repository.AccountRepository
import org.libremail.reporting.AppLog
import org.libremail.reporting.RingLogBuffer
import kotlin.test.assertEquals
import kotlin.test.assertFalse
import kotlin.test.assertNotEquals
import kotlin.test.assertNull
import kotlin.test.assertTrue
/**
* Issue #326 migrated this ViewModel's logging to [AppLog]: a [RingLogBuffer] is installed here and
* assertions about what got logged are against [logBuffer] — including that a failed sign-in whose
* throwable carries the account email never lets that email reach the buffer (the seam's
* `StackTraceScrubber` must redact it).
*/
@OptIn(ExperimentalCoroutinesApi::class)
class AccountSetupViewModelTest {
private val dispatcher = UnconfinedTestDispatcher()
private val logBuffer = RingLogBuffer()
@Before
fun setUp() = Dispatchers.setMain(dispatcher)
fun setUp() {
Dispatchers.setMain(dispatcher)
// android.util.Log is a no-op stub that throws "not mocked" in JVM tests, and AppLog always
// forwards to it; stub every level up front, then install a real buffer so breadcrumbs can be
// asserted for real instead of via `verify { Log... }`.
mockkStatic(Log::class)
every { Log.d(any(), any()) } returns 0
every { Log.d(any(), any(), any()) } returns 0
every { Log.i(any(), any()) } returns 0
every { Log.w(any<String>(), any<String>()) } returns 0
every { Log.w(any<String>(), any<String>(), any()) } returns 0
every { Log.e(any(), any(), any()) } returns 0
AppLog.install(logBuffer)
}
@After
fun tearDown() {
@@ -125,12 +148,15 @@ class AccountSetupViewModelTest {
assertEquals("outlook:me@outlook.com", vm.state.value.addedAccountId)
assertNull(vm.state.value.error)
coVerify { accounts.addOutlookAccount("me@outlook.com", "tok", "{}") }
// Issue #326: the success breadcrumb never carries the account email.
val entry = logBuffer.snapshot().single()
assertEquals('I', entry.level)
assertEquals("Outlook account added", entry.message)
assertFalse(entry.message.contains("@"))
}
@Test
fun `a failed token exchange returns to idle with the error surfaced`() = runTest(dispatcher) {
mockkStatic(Log::class)
every { Log.d(any(), any(), any()) } returns 0
val manager = mockk<OutlookAuthManager>(relaxed = true)
coEvery { manager.exchangeToken(any()) } throws IllegalStateException("Token exchange failed")
val vm = viewModel(outlookAuthManager = manager)
@@ -141,12 +167,15 @@ class AccountSetupViewModelTest {
assertEquals(SetupStatus.IDLE, vm.state.value.status)
assertEquals("Token exchange failed", vm.state.value.error)
assertNull(vm.state.value.addedAccountId)
// Issue #326: the migrated Log.d -> AppLog.d call records a debug breadcrumb in the buffer
// (unlike raw Log.d, this survives release builds — only the Logcat mirror is stripped there).
val entry = logBuffer.snapshot().single()
assertEquals('D', entry.level)
assertTrue(entry.message.startsWith("Outlook sign-in failed after redirect"), entry.message)
}
@Test
fun `a persistence failure after exchange returns to idle with an error`() = runTest(dispatcher) {
mockkStatic(Log::class)
every { Log.d(any(), any(), any()) } returns 0
val manager = mockk<OutlookAuthManager>(relaxed = true)
coEvery { manager.exchangeToken(any()) } returns
OAuthResult(email = "me@outlook.com", accessToken = "tok", authStateJson = "{}")
@@ -162,6 +191,26 @@ class AccountSetupViewModelTest {
assertEquals("IMAP verification failed", vm.state.value.error)
}
@Test
fun `a failure whose message carries the account email is scrubbed before it reaches the buffer`() =
runTest(dispatcher) {
// Drives a failing Outlook sign-in with a known test email embedded in the thrown
// exception's message, and asserts no buffer line contains that address: AppLog.d's
// StackTraceScrubber must redact it from the throwable's recorded stack trace text.
val knownTestEmail = "me@outlook.com"
val manager = mockk<OutlookAuthManager>(relaxed = true)
coEvery { manager.exchangeToken(any()) } throws
IllegalStateException("Token exchange failed for $knownTestEmail")
val vm = viewModel(outlookAuthManager = manager)
vm.onOutlookResult(mockk<Intent>(relaxed = true))
advanceUntilIdle()
val snapshot = logBuffer.snapshot()
assertTrue(snapshot.isNotEmpty())
snapshot.forEach { entry -> assertFalse(entry.message.contains(knownTestEmail), entry.message) }
}
@Test
fun `consumeError clears a surfaced error`() {
val vm = viewModel()
@@ -40,10 +40,13 @@ import org.libremail.data.security.PassphraseSession
import org.libremail.data.settings.AppSettings
import org.libremail.data.settings.SettingsRepository
import org.libremail.data.sync.SyncScheduler
import org.libremail.reporting.AppLog
import org.libremail.reporting.RingLogBuffer
import org.libremail.restart.ProcessRestarter
import java.util.concurrent.ExecutionException
import java.util.concurrent.TimeoutException
import kotlin.test.assertEquals
import kotlin.test.assertFalse
import kotlin.test.assertIs
import kotlin.test.assertNotEquals
import kotlin.test.assertTrue
@@ -65,14 +68,33 @@ import kotlin.test.assertTrue
* restart, and CLEAR_AND_REQUIRE_AUTH keeps app-lock on) and the `onAuthenticated` unlock/arm
* classification (OK / UNRECOVERABLE / RETRY), so a mutation that wipes user data or drops the lock is
* caught here rather than only on a device.
*
* Issue #326 migrated this ViewModel's logging to [AppLog], so a [RingLogBuffer] is installed here and
* assertions about what got logged are against [logBuffer] — never `verify { Log... }` — matching how
* the rest of the suite treats [AppLog] as the seam instead of Logcat.
*/
@OptIn(ExperimentalCoroutinesApi::class)
class AppLockViewModelTest {
private val dispatcher = UnconfinedTestDispatcher()
private val logBuffer = RingLogBuffer()
@Before
fun setUp() = Dispatchers.setMain(dispatcher)
fun setUp() {
Dispatchers.setMain(dispatcher)
// android.util.Log is a no-op stub that throws "not mocked" in JVM tests, and AppLog always
// forwards to it; stub every level up front (regardless of which breadcrumbs a given test
// exercises) so no test needs its own ad-hoc Log mocking, then install a real buffer so
// breadcrumbs can be asserted for real instead of via `verify { Log... }`.
mockkStatic(Log::class)
every { Log.d(any(), any()) } returns 0
every { Log.d(any(), any(), any()) } returns 0
every { Log.i(any(), any()) } returns 0
every { Log.w(any<String>(), any<String>()) } returns 0
every { Log.w(any<String>(), any<String>(), any()) } returns 0
every { Log.e(any(), any(), any()) } returns 0
AppLog.install(logBuffer)
}
@After
fun tearDown() {
@@ -174,6 +196,8 @@ class AppLockViewModelTest {
// anyway (the periodic sync will still refill the wiped cache later).
verify { future.get(any(), any()) }
verify { processRestarter.restart() }
// Issue #326: the swallowed timeout is still breadcrumbed so a report can explain the delay.
assertTrue(logBuffer.snapshot().any { it.message.startsWith("re-sync enqueue not confirmed within timeout") })
}
@Test
@@ -189,6 +213,8 @@ class AppLockViewModelTest {
// A failed enqueue is swallowed like a timeout: recovery restarts anyway.
verify { future.get(any(), any()) }
verify { processRestarter.restart() }
// Issue #326: the swallowed failure is breadcrumbed too.
assertTrue(logBuffer.snapshot().any { it.message.startsWith("re-sync enqueue failed; restarting anyway") })
}
@Test
@@ -208,11 +234,14 @@ class AppLockViewModelTest {
assertTrue(reInterrupted)
verify { future.get(any(), any()) }
verify { processRestarter.restart() }
// Issue #326: the swallowed interrupt is breadcrumbed too.
assertTrue(
logBuffer.snapshot().any { it.message.startsWith("interrupted awaiting re-sync enqueue") },
)
}
@Test
fun `onAuthenticated rethrows a cancellation while unwrapping and never wipes the cache`() = runTest(dispatcher) {
stubLog()
val session = mockk<PassphraseSession>(relaxed = true)
every { session.isUnlocked() } returns false
val databaseKeyStore = mockk<DatabaseKeyStore>(relaxed = true)
@@ -333,6 +362,12 @@ class AppLockViewModelTest {
future.get(any(), any())
processRestarter.restart()
}
// Issue #326: the clear+restart recovery path is breadcrumbed with the disableAppLock flag.
assertTrue(
logBuffer.snapshot().any {
it.level == 'W' && it.message == "clearing encrypted cache and restarting (disableAppLock=true)"
},
)
}
@Test
@@ -360,6 +395,12 @@ class AppLockViewModelTest {
processRestarter.restart()
}
coVerify(exactly = 0) { settingsRepository.setAppLock(false) }
// Issue #326: app-lock stays on here, so the breadcrumb reflects disableAppLock=false.
assertTrue(
logBuffer.snapshot().any {
it.level == 'W' && it.message == "clearing encrypted cache and restarting (disableAppLock=false)"
},
)
}
@Test
@@ -372,6 +413,8 @@ class AppLockViewModelTest {
assertIs<AppLockUiState.Unlocked>(vm.uiState.value)
verify(exactly = 0) { processRestarter.restart() }
// Issue #326: every foreground pass with app-lock on records its (non-PII) LockAction decision.
assertEquals("app-lock foreground decision: PROCEED", logBuffer.snapshot().single().message)
}
@Test
@@ -405,6 +448,11 @@ class AppLockViewModelTest {
assertIs<AppLockUiState.Unlocked>(vm.uiState.value)
coVerify(exactly = 0) { databaseKeyStore.unlockWithAuth() }
coVerify(exactly = 0) { databaseKeyStore.sealWithAuth() }
// Issue #326: a successful unlock records a breadcrumb that the cache became readable, with
// no PII (account id/email never reach this ViewModel).
val entry = logBuffer.snapshot().single()
assertEquals('I', entry.level)
assertEquals("auth seal unlocked; cache readable", entry.message)
}
@Test
@@ -434,7 +482,6 @@ class AppLockViewModelTest {
@Test
fun `onAuthenticated clears the cache when the auth-bound key was deleted`() = runTest(dispatcher) {
stubLog()
val (future, syncScheduler) = enqueueingScheduler()
val session = mockk<PassphraseSession>(relaxed = true)
every { session.isUnlocked() } returns false
@@ -462,11 +509,15 @@ class AppLockViewModelTest {
future.get(any(), any())
processRestarter.restart()
}
// Issue #326: both the classification that made this UNRECOVERABLE and the ViewModel's own
// "clearing the cache" breadcrumb are recorded.
val messages = logBuffer.snapshot().filter { it.level == 'W' }.map { it.message }
assertTrue("auth-sealed passphrase present but key was deleted; cache unrecoverable" in messages)
assertTrue("encrypted cache passphrase unrecoverable; clearing cache" in messages)
}
@Test
fun `onAuthenticated clears the cache when the auth-bound key was permanently invalidated`() = runTest(dispatcher) {
stubLog()
val (_, syncScheduler) = enqueueingScheduler()
val session = mockk<PassphraseSession>(relaxed = true)
every { session.isUnlocked() } returns false
@@ -490,11 +541,12 @@ class AppLockViewModelTest {
coVerify { databaseKeyStore.setClearPending() }
verify { processRestarter.restart() }
// Issue #326: the permanent-invalidation classification is breadcrumbed too.
assertTrue(logBuffer.snapshot().any { it.message.startsWith("auth-bound key permanently invalidated") })
}
@Test
fun `onAuthenticated re-locks for a retry when the auth window elapsed`() = runTest(dispatcher) {
stubLog()
val gate = mockk<AppLockGate>(relaxed = true)
every { gate.state } returns LockState.LOCKED
val session = mockk<PassphraseSession>(relaxed = true)
@@ -520,11 +572,14 @@ class AppLockViewModelTest {
verify { gate.lock() }
assertIs<AppLockUiState.Locked>(vm.uiState.value)
verify(exactly = 0) { processRestarter.restart() }
// Issue #326: breadcrumbed with the scrubbed throwable attached (the 3-arg AppLog.w overload),
// not just the bare message — the trailing newline is the scrubbed stack trace.
val entry = logBuffer.snapshot().single { it.message.startsWith("auth window elapsed before unwrap") }
assertTrue(entry.message.contains("\n"), entry.message)
}
@Test
fun `onAuthenticated re-locks for a retry on an ambiguous unwrap failure`() = runTest(dispatcher) {
stubLog()
val gate = mockk<AppLockGate>(relaxed = true)
every { gate.state } returns LockState.LOCKED
val session = mockk<PassphraseSession>(relaxed = true)
@@ -549,6 +604,12 @@ class AppLockViewModelTest {
// An ambiguous error must NOT wipe the cache on an otherwise-successful auth: re-lock + retry.
verify { gate.lock() }
verify(exactly = 0) { processRestarter.restart() }
// Issue #326: the catch-all classification is breadcrumbed too.
assertTrue(
logBuffer.snapshot().any {
it.message.startsWith("unexpected failure unwrapping auth-sealed passphrase")
},
)
}
@Test
@@ -600,7 +661,6 @@ class AppLockViewModelTest {
@Test
fun `onAuthenticated re-locks for a retry when arming the auth seal fails`() = runTest(dispatcher) {
stubLog()
val gate = mockk<AppLockGate>(relaxed = true)
every { gate.state } returns LockState.LOCKED
val session = mockk<PassphraseSession>(relaxed = true)
@@ -623,6 +683,25 @@ class AppLockViewModelTest {
verify { gate.lock() }
assertIs<AppLockUiState.Locked>(vm.uiState.value)
verify(exactly = 0) { processRestarter.restart() }
// Issue #326: arming failures are breadcrumbed too.
assertTrue(logBuffer.snapshot().any { it.message.startsWith("arming auth seal failed") })
}
// --- AppLog breadcrumbs carry no PII (issue #326) ---------------------------------------------
@Test
fun `a cache-clear recovery breadcrumb never contains an email address`() = runTest(dispatcher) {
// AppLockViewModel only ever sees keystore/auth exceptions and enum decisions — never an
// account id or email — so no buffer line it writes should ever contain an "@". This pins that
// contract as the ViewModel evolves, rather than relying on code review alone to catch a leak.
val vm = clearOnForegroundViewModel()
vm.onForeground()
advanceUntilIdle()
val snapshot = logBuffer.snapshot()
assertTrue(snapshot.isNotEmpty())
snapshot.forEach { entry -> assertFalse(entry.message.contains("@"), entry.message) }
}
/** A [SyncScheduler] whose `syncNow()` returns an [Operation] whose result future can be stubbed. */
@@ -646,9 +725,6 @@ class AppLockViewModelTest {
): AppLockViewModel {
mockkStatic(SystemClock::class)
every { SystemClock.elapsedRealtime() } returns 1_000L
// android.util.Log is a no-op stub that throws "not mocked" in JVM tests; the timeout path logs.
mockkStatic(Log::class)
every { Log.w(any<String>(), any<String>(), any<Throwable>()) } returns 0
mockkObject(KeyInvalidationPolicy)
every { KeyInvalidationPolicy.decide(any(), any(), any(), any()) } returns LockAction.CLEAR_AND_REQUIRE_AUTH
return viewModel(
@@ -674,7 +750,6 @@ class AppLockViewModelTest {
): AppLockViewModel {
mockkStatic(SystemClock::class)
every { SystemClock.elapsedRealtime() } returns FOREGROUND_AT
stubLog()
mockkObject(KeyInvalidationPolicy)
every { KeyInvalidationPolicy.decide(any(), any(), any(), any()) } returns action
return viewModel(
@@ -686,13 +761,6 @@ class AppLockViewModelTest {
)
}
/** android.util.Log is a no-op stub that throws "not mocked" in JVM tests; the recovery paths log. */
private fun stubLog() {
mockkStatic(Log::class)
every { Log.w(any<String>(), any<String>()) } returns 0
every { Log.w(any<String>(), any<String>(), any<Throwable>()) } returns 0
}
private companion object {
const val FOREGROUND_AT = 1_000L
}