Merge main into ci-342-traffic-control-python

2026-07-04 22:29:32 -05:00
parent a34db54b97 785c6aa6c6
commit 647490c1a8
5 changed files with 221 additions and 70 deletions
@@ -2,7 +2,6 @@
 package org.libremail.data.sync

 import android.content.Context
-import android.util.Log
 import androidx.hilt.work.HiltWorker
 import androidx.work.CoroutineWorker
 import androidx.work.WorkerParameters
@@ -24,6 +23,8 @@ import org.libremail.mail.GraphSendException
 import org.libremail.mail.GraphSender
 import org.libremail.mail.SendableAttachment
 import org.libremail.mail.SmtpSender
+import org.libremail.reporting.AppLog
+import org.libremail.reporting.accountLogRef
 import java.io.File
 import kotlin.coroutines.cancellation.CancellationException

@@ -57,66 +58,89 @@ class SendWorker @AssistedInject constructor(
        val attachmentUriGrants = this.attachmentUriGrants.get()
        val pending = outboxDao.getAll()
        if (pending.isEmpty()) return Result.success()
+        AppLog.i(TAG, "outbox drain: ${pending.size} queued")

        var anyFailed = false
        for (entity in pending) {
-            val attachmentDir = File(applicationContext.cacheDir, "outbox/${entity.id}")
-            val account = accountDao.getById(entity.accountId)?.toDomain()
-            if (account == null) {
-                outboxDao.delete(entity.id) // account removed — drop the queued message
-                attachmentDir.deleteRecursively()
-                attachmentUriGrants.releaseUnreferenced(entity.attachmentUris())
-                continue
-            }
-            runCatching {
-                val message = OutgoingMessage(
-                    accountId = entity.accountId,
-                    to = entity.toAddresses,
-                    cc = entity.ccAddresses,
-                    bcc = entity.bccAddresses,
-                    subject = entity.subject,
-                    body = entity.body,
-                    bodyHtml = entity.bodyHtml,
-                )
-                val attachments = stagedAttachments(attachmentDir, entity.attachments.toOutgoingAttachments())
-                if (account.authType == AuthType.OAUTH_OUTLOOK) {
-                    sendOutlook(connectionFactory, account, message, attachments)
-                } else {
-                    smtpSender.send(
-                        connectionFactory.smtpParamsFor(account),
-                        from = account.email,
-                        message = message,
-                        attachments = attachments,
-                    )
-                }
-            }.fold(
-                onSuccess = {
-                    outboxDao.delete(entity.id)
-                    attachmentDir.deleteRecursively()
-                    // The picked bytes were staged at enqueue; with the row sent, drop the persistable
-                    // grant unless a live draft/outbox row still references the same URI (security review).
-                    attachmentUriGrants.releaseUnreferenced(entity.attachmentUris())
-                },
-                onFailure = { e ->
-                    if (e is GraphSendException && e.mayHaveSent) {
-                        // Graph may already have delivered this; auto-retrying (or any other send)
-                        // would duplicate it, so leave it queued with a clear status and let the
-                        // user decide. Not counted as a failure, so WorkManager won't auto-retry.
-                        outboxDao.setError(
-                            entity.id,
-                            "Send status unknown — check your Sent folder, then retry or cancel",
-                        )
-                    } else {
-                        outboxDao.setError(entity.id, e.message)
-                        anyFailed = true
-                    }
-                },
-            )
+            val failed = sendQueued(entity, outboxDao, accountDao, connectionFactory, attachmentUriGrants)
+            if (failed) anyFailed = true
        }
        // Retry (with WorkManager backoff) so failed sends are reattempted when conditions improve.
        return if (anyFailed) Result.retry() else Result.success()
    }

+    /**
+     * Sends one queued [entity] — or drops it if its account was removed — updating the outbox row
+     * and releasing its staged attachment grant. Returns true if the send genuinely failed (should
+     * count toward a WorkManager retry); the ambiguous "may have sent" Graph case returns false, since
+     * it is deliberately left queued rather than retried (see [sendOutlook]).
+     */
+    private suspend fun sendQueued(
+        entity: OutboxEntity,
+        outboxDao: OutboxDao,
+        accountDao: AccountDao,
+        connectionFactory: MailConnectionFactory,
+        attachmentUriGrants: AttachmentUriGrants,
+    ): Boolean {
+        val attachmentDir = File(applicationContext.cacheDir, "outbox/${entity.id}")
+        val account = accountDao.getById(entity.accountId)?.toDomain()
+        if (account == null) {
+            outboxDao.delete(entity.id) // account removed — drop the queued message
+            attachmentDir.deleteRecursively()
+            attachmentUriGrants.releaseUnreferenced(entity.attachmentUris())
+            return false
+        }
+        var failed = false
+        runCatching {
+            val message = OutgoingMessage(
+                accountId = entity.accountId,
+                to = entity.toAddresses,
+                cc = entity.ccAddresses,
+                bcc = entity.bccAddresses,
+                subject = entity.subject,
+                body = entity.body,
+                bodyHtml = entity.bodyHtml,
+            )
+            val attachments = stagedAttachments(attachmentDir, entity.attachments.toOutgoingAttachments())
+            if (account.authType == AuthType.OAUTH_OUTLOOK) {
+                sendOutlook(connectionFactory, account, message, attachments)
+            } else {
+                smtpSender.send(
+                    connectionFactory.smtpParamsFor(account),
+                    from = account.email,
+                    message = message,
+                    attachments = attachments,
+                )
+            }
+        }.fold(
+            onSuccess = {
+                outboxDao.delete(entity.id)
+                attachmentDir.deleteRecursively()
+                // The picked bytes were staged at enqueue; with the row sent, drop the persistable
+                // grant unless a live draft/outbox row still references the same URI (security review).
+                attachmentUriGrants.releaseUnreferenced(entity.attachmentUris())
+                val via = if (account.authType == AuthType.OAUTH_OUTLOOK) "Graph" else "SMTP"
+                AppLog.i(TAG, "sent ${accountLogRef(account.id)} via $via")
+            },
+            onFailure = { e ->
+                if (e is GraphSendException && e.mayHaveSent) {
+                    // Graph may already have delivered this; auto-retrying (or any other send) would
+                    // duplicate it, so leave it queued with a clear status and let the user decide.
+                    // Not counted as a failure, so WorkManager won't auto-retry.
+                    outboxDao.setError(
+                        entity.id,
+                        "Send status unknown — check your Sent folder, then retry or cancel",
+                    )
+                } else {
+                    outboxDao.setError(entity.id, e.message)
+                    failed = true
+                    AppLog.w(TAG, "send failed for ${accountLogRef(account.id)}; will retry")
+                }
+            },
+        )
+        return failed
+    }
+
    /**
     * Outlook prefers Microsoft Graph. Fall back to SMTP only when Graph definitely did NOT send
     * (a rejection, a pre-send/transport error, or a token failure); never fall back when the Graph
@@ -143,7 +167,7 @@ class SendWorker @AssistedInject constructor(
            throw e
        } catch (e: Exception) {
            // Graph was never reached (e.g. token refresh failed) — SMTP cannot duplicate it.
-            Log.w(TAG, "Graph send failed for ${account.email}; falling back to SMTP", e)
+            AppLog.w(TAG, "Graph send failed for ${accountLogRef(account.id)}; falling back to SMTP", e)
            smtpSender.send(
                connectionFactory.smtpParamsFor(account),
                from = account.email,
@@ -1,7 +1,6 @@
 // SPDX-License-Identifier: GPL-3.0-or-later
 package org.libremail.mail

-import android.util.Log
 import jakarta.mail.FetchProfile
 import jakarta.mail.Flags
 import jakarta.mail.Folder
@@ -33,6 +32,7 @@ import org.eclipse.angus.mail.imap.IMAPFolder
 import org.eclipse.angus.mail.imap.IMAPMessage
 import org.libremail.domain.model.ImapConnectionParams
 import org.libremail.domain.model.MailSecurity
+import org.libremail.reporting.AppLog
 import java.util.Properties
 import javax.inject.Inject
 import javax.inject.Singleton
@@ -474,12 +474,12 @@ class ImapClient(private val reuseConnections: Boolean) {
            runCatching { store.close() }
            throw e
        }
-        Log.d(TAG, "IDLE connected")
+        AppLog.d(TAG, "IDLE connected")

        val pushes = Channel<Unit>(Channel.CONFLATED)
        inbox.addMessageCountListener(object : MessageCountAdapter() {
            override fun messagesAdded(event: MessageCountEvent) {
-                Log.d(TAG, "IDLE push: ${event.messages.size} new message(s)")
+                AppLog.d(TAG, "IDLE push: ${event.messages.size} new message(s)")
                pushes.trySend(Unit)
            }
        })
@@ -8,7 +8,6 @@ import android.content.Intent
 import android.content.pm.PackageManager
 import android.content.pm.ServiceInfo
 import android.os.IBinder
-import android.util.Log
 import androidx.core.app.NotificationManagerCompat
 import androidx.core.app.ServiceCompat
 import androidx.core.content.ContextCompat
@@ -38,6 +37,7 @@ import org.libremail.domain.model.Account
 import org.libremail.mail.ImapClient
 import org.libremail.power.BatteryStatusProvider
 import org.libremail.reporting.AppLog
+import org.libremail.reporting.accountLogRef
 import javax.inject.Inject

 /**
@@ -91,7 +91,7 @@ class IdleService : Service() {
                // Can't open the encrypted DB without the user present. Defer (stop) and let the app
                // restart push after the next unlock, rather than block the service and ANR.
                if (cacheGuard.isCacheLocked()) {
-                    Log.i(TAG, "encrypted cache locked; deferring IDLE push until the app is unlocked")
+                    AppLog.i(TAG, "encrypted cache locked; deferring IDLE push until the app is unlocked")
                    stopSelf()
                    return@launch
                }
@@ -200,6 +200,7 @@ class IdleService : Service() {
     * idle()'s on-connect sync, so no mail is missed across renewals.
     */
    private suspend fun watchAccount(account: Account) {
+        AppLog.i(TAG, "IDLE watch start ${accountLogRef(account.id)}")
        var backoffMs = INITIAL_BACKOFF_MS
        while (scope.isActive) {
            try {
@@ -212,7 +213,7 @@ class IdleService : Service() {
            } catch (e: CancellationException) {
                throw e
            } catch (e: Exception) {
-                Log.w(TAG, "IDLE for ${account.email} dropped; retrying in ${backoffMs}ms", e)
+                AppLog.w(TAG, "IDLE for ${accountLogRef(account.id)} dropped; retrying in ${backoffMs}ms", e)
                delay(backoffMs)
                backoffMs = (backoffMs * 2).coerceAtMost(MAX_BACKOFF_MS)
            }
@@ -2,8 +2,9 @@
 package org.libremail.data.sync

 import android.content.Context
-import android.util.Log
 import androidx.work.ListenableWorker.Result
+import com.icegreen.greenmail.util.GreenMail
+import com.icegreen.greenmail.util.ServerSetupTest
 import dagger.Lazy
 import io.mockk.coEvery
 import io.mockk.coVerify
@@ -25,12 +26,16 @@ import org.libremail.data.local.entity.OutboxEntity
 import org.libremail.data.local.entity.ServerConfigEmbedded
 import org.libremail.data.local.toOutgoingAttachmentsJson
 import org.libremail.data.security.EncryptedCacheGuard
+import org.libremail.domain.model.MailSecurity
 import org.libremail.domain.model.OutgoingAttachment
 import org.libremail.domain.model.SmtpParams
 import org.libremail.mail.GraphSendException
 import org.libremail.mail.GraphSender
 import org.libremail.mail.SendableAttachment
 import org.libremail.mail.SmtpSender
+import org.libremail.reporting.AppLog
+import org.libremail.reporting.RingLogBuffer
+import org.libremail.reporting.accountLogRef
 import java.io.File
 import kotlin.test.assertEquals
 import kotlin.test.assertFalse
@@ -42,6 +47,11 @@ import kotlin.test.assertTrue
 * the outbox: sending each queued message over SMTP or Microsoft Graph, deleting it on success,
 * flagging failures for a retry, and — crucially for the "may have sent" case — never auto-retrying
 * a Graph request that might already have delivered.
+ *
+ * It also logs breadcrumbs via [AppLog] (outbox-drain size, per-message send result, the Graph→SMTP
+ * fallback) — asserted here against a real [RingLogBuffer] rather than a mocked `Log`, per #328. Those
+ * assertions double as the regression cover for #297: `account.email` must never reach a log line,
+ * only the non-PII [accountLogRef].
 */
 class SendWorkerTest {

@@ -56,6 +66,7 @@ class SendWorkerTest {
    private val lazyConnection = mockk<Lazy<MailConnectionFactory>> { every { get() } returns connectionFactory }
    private val lazyGrants = mockk<Lazy<AttachmentUriGrants>> { every { get() } returns attachmentUriGrants }
    private val cacheGuard = mockk<EncryptedCacheGuard>()
+    private val logBuffer = RingLogBuffer()

    private lateinit var cacheDir: File
    private lateinit var appContext: Context
@@ -66,6 +77,16 @@ class SendWorkerTest {
        appContext = mockk(relaxed = true)
        every { appContext.cacheDir } returns cacheDir
        coEvery { cacheGuard.isCacheLocked() } returns false
+        // AppLog forwards every call to Logcat; stub the Android stub (by fully-qualified name, so
+        // this file — like the production code it exercises — never imports android.util.Log; only
+        // AppLog.kt may) so a JVM unit test doesn't crash on the unmocked method, and install a real
+        // buffer so the breadcrumb + #297 no-PII assertions below read actual recorded lines rather
+        // than a `Log` verification.
+        mockkStatic(android.util.Log::class)
+        every { android.util.Log.i(any(), any()) } returns 0
+        every { android.util.Log.w(any<String>(), any<String>()) } returns 0
+        every { android.util.Log.w(any<String>(), any<String>(), any()) } returns 0
+        AppLog.install(logBuffer)
    }

    @After
@@ -128,6 +149,17 @@ class SendWorkerTest {
        coVerify(exactly = 0) { smtpSender.send(any(), any(), any(), any()) }
    }

+    @Test
+    fun `doWork logs the outbox-drain breadcrumb with the queued count`() = runTest {
+        coEvery { outboxDao.getAll() } returns listOf(entity())
+        coEvery { accountDao.getById("acct") } returns account("acct", "PASSWORD_IMAP")
+        coEvery { connectionFactory.smtpParamsFor(any()) } returns mockk<SmtpParams>()
+
+        worker().doWork()
+
+        assertTrue(logBuffer.snapshot().map { it.message }.contains("outbox drain: 1 queued"))
+    }
+
    @Test
    fun `drops a queued message whose account was removed`() = runTest {
        val row = entity()
@@ -142,7 +174,7 @@ class SendWorkerTest {
    }

    @Test
-    fun `sends a password account message over SMTP then clears it`() = runTest {
+    fun `sends a password account message over SMTP then clears it, logging a PII-free breadcrumb`() = runTest {
        coEvery { outboxDao.getAll() } returns listOf(entity())
        coEvery { accountDao.getById("acct") } returns account("acct", "PASSWORD_IMAP")
        coEvery { connectionFactory.smtpParamsFor(any()) } returns mockk<SmtpParams>()
@@ -152,10 +184,13 @@ class SendWorkerTest {
        coVerify { smtpSender.send(any(), "acct@example.org", any(), any()) }
        coVerify { outboxDao.delete("m1") }
        coVerify { attachmentUriGrants.releaseUnreferenced(any()) }
+        val messages = logBuffer.snapshot().map { it.message }
+        assertTrue(messages.contains("sent ${accountLogRef("acct")} via SMTP"), "messages=$messages")
+        messages.forEach { assertFalse(it.contains("acct@example.org"), it) }
    }

    @Test
-    fun `an SMTP failure flags the row and retries`() = runTest {
+    fun `an SMTP failure flags the row, retries, and logs a PII-free failure breadcrumb`() = runTest {
        coEvery { outboxDao.getAll() } returns listOf(entity())
        coEvery { accountDao.getById("acct") } returns account("acct", "PASSWORD_IMAP")
        coEvery { connectionFactory.smtpParamsFor(any()) } returns mockk<SmtpParams>()
@@ -165,10 +200,13 @@ class SendWorkerTest {

        coVerify { outboxDao.setError("m1", "smtp down") }
        coVerify(exactly = 0) { outboxDao.delete(any()) }
+        val messages = logBuffer.snapshot().map { it.message }
+        assertTrue(messages.contains("send failed for ${accountLogRef("acct")}; will retry"), "messages=$messages")
+        messages.forEach { assertFalse(it.contains("acct@example.org"), it) }
    }

    @Test
-    fun `sends an Outlook message over Graph`() = runTest {
+    fun `sends an Outlook message over Graph, logging a PII-free breadcrumb`() = runTest {
        coEvery { outboxDao.getAll() } returns listOf(entity())
        coEvery { accountDao.getById("acct") } returns account("acct", "OAUTH_OUTLOOK")
        coEvery { connectionFactory.graphTokenFor(any()) } returns "graph-token"
@@ -178,6 +216,9 @@ class SendWorkerTest {
        coVerify { graphSender.send("graph-token", any(), any()) }
        coVerify { outboxDao.delete("m1") }
        coVerify(exactly = 0) { smtpSender.send(any(), any(), any(), any()) }
+        val messages = logBuffer.snapshot().map { it.message }
+        assertTrue(messages.contains("sent ${accountLogRef("acct")} via Graph"), "messages=$messages")
+        messages.forEach { assertFalse(it.contains("acct@example.org"), it) }
    }

    @Test
@@ -212,9 +253,7 @@ class SendWorkerTest {
    }

    @Test
-    fun `a Graph transport error falls back to SMTP`() = runTest {
-        mockkStatic(Log::class)
-        every { Log.w(any(), any<String>(), any<Throwable>()) } returns 0
+    fun `a Graph transport error falls back to SMTP and logs a PII-free fallback breadcrumb`() = runTest {
        coEvery { outboxDao.getAll() } returns listOf(entity())
        coEvery { accountDao.getById("acct") } returns account("acct", "OAUTH_OUTLOOK")
        coEvery { connectionFactory.graphTokenFor(any()) } throws RuntimeException("token refresh failed")
@@ -224,6 +263,75 @@ class SendWorkerTest {

        coVerify { smtpSender.send(any(), "acct@example.org", any(), any()) }
        coVerify { outboxDao.delete("m1") }
+        val messages = logBuffer.snapshot().map { it.message }
+        assertTrue(
+            messages.any { it.startsWith("Graph send failed for ${accountLogRef("acct")}; falling back to SMTP") },
+            "messages=$messages",
+        )
+        messages.forEach { assertFalse(it.contains("acct@example.org"), it) }
+    }
+
+    @Test
+    fun `regression #297 - no send breadcrumb ever contains the account email`() = runTest {
+        coEvery { outboxDao.getAll() } returns listOf(entity())
+        coEvery { accountDao.getById("acct") } returns account("acct", "OAUTH_OUTLOOK")
+        coEvery { connectionFactory.graphTokenFor(any()) } throws RuntimeException("token refresh failed")
+        coEvery { connectionFactory.smtpParamsFor(any()) } returns mockk<SmtpParams>()
+
+        worker().doWork()
+
+        val snapshot = logBuffer.snapshot()
+        // This path logs the outbox-drain, the Graph->SMTP fallback (with a scrubbed throwable), and
+        // the send-result breadcrumbs — the richest set of log lines for one message. None may carry
+        // the account's raw email, only the non-reversible accountLogRef.
+        assertTrue(snapshot.isNotEmpty(), "expected breadcrumbs to be recorded")
+        snapshot.forEach { entry ->
+            assertFalse(entry.message.contains("acct@example.org"), entry.message)
+            assertFalse(entry.message.contains("@example.org"), entry.message)
+        }
+    }
+
+    @Test
+    fun `sends over a real SMTP server end-to-end and logs a PII-free breadcrumb`() = runTest {
+        // The "connectivity/send" E2E surface for this ticket: a real SmtpSender talking to a real
+        // (in-process) SMTP server, rather than the mocked smtpSender used by the tests above.
+        val greenMail = GreenMail(ServerSetupTest.SMTP)
+        greenMail.start()
+        greenMail.setUser("acct@example.org", "smtp-secret")
+        try {
+            coEvery { outboxDao.getAll() } returns listOf(entity())
+            coEvery { accountDao.getById("acct") } returns account("acct", "PASSWORD_IMAP")
+            coEvery { connectionFactory.smtpParamsFor(any()) } returns SmtpParams(
+                host = "127.0.0.1",
+                port = greenMail.smtp.port,
+                security = MailSecurity.NONE,
+                username = "acct@example.org",
+                secret = "smtp-secret",
+                useXoauth2 = false,
+            )
+            val realSmtpWorker = SendWorker(
+                appContext,
+                mockk(relaxed = true),
+                lazyOutbox,
+                lazyAccount,
+                SmtpSender(),
+                graphSender,
+                lazyConnection,
+                cacheGuard,
+                lazyGrants,
+            )
+
+            assertEquals(Result.success(), realSmtpWorker.doWork())
+            greenMail.waitForIncomingEmail(1)
+
+            assertEquals(1, greenMail.receivedMessages.size)
+            coVerify { outboxDao.delete("m1") }
+            val messages = logBuffer.snapshot().map { it.message }
+            assertTrue(messages.contains("sent ${accountLogRef("acct")} via SMTP"), "messages=$messages")
+            messages.forEach { assertFalse(it.contains("acct@example.org"), it) }
+        } finally {
+            greenMail.stop()
+        }
    }

    @Test
@@ -1,7 +1,6 @@
 // SPDX-License-Identifier: GPL-3.0-or-later
 package org.libremail.mail

-import android.util.Log
 import com.icegreen.greenmail.util.GreenMail
 import com.icegreen.greenmail.util.GreenMailUtil
 import com.icegreen.greenmail.util.ServerSetupTest
@@ -31,6 +30,8 @@ import org.junit.Before
 import org.junit.Test
 import org.libremail.domain.model.ImapConnectionParams
 import org.libremail.domain.model.MailSecurity
+import org.libremail.reporting.AppLog
+import org.libremail.reporting.RingLogBuffer
 import java.util.Properties
 import kotlin.test.assertContentEquals
 import kotlin.test.assertEquals
@@ -359,8 +360,14 @@ class ImapClientTest {

    @Test
    fun `idle syncs once on connect, again on newly delivered mail, and stops on cancel`() = runBlocking {
-        mockkStatic(Log::class) // idle() logs connect/push at debug level
-        every { Log.d(any(), any()) } returns 0
+        // idle() logs connect/push breadcrumbs via AppLog, which forwards to Logcat; stub the Android
+        // stub (by fully-qualified name, so this file never imports android.util.Log — only AppLog.kt
+        // may) so the JVM test doesn't crash on the unmocked method, and install a real buffer so the
+        // breadcrumbs can be asserted directly instead of via a Log verification.
+        mockkStatic(android.util.Log::class)
+        every { android.util.Log.d(any(), any()) } returns 0
+        val buffer = RingLogBuffer()
+        AppLog.install(buffer)
        val activity = Channel<Unit>(Channel.UNLIMITED)
        val job = launch(Dispatchers.IO) { client.idle(params()) { activity.send(Unit) } }
        try {
@@ -373,6 +380,17 @@ class ImapClientTest {
            job.cancelAndJoin() // cancelling closes the connection and unblocks idle()
        }
        assertTrue(job.isCompleted, "the idle loop must terminate on cancellation")
+
+        val messages = buffer.snapshot().map { it.message }
+        assertTrue(messages.contains("IDLE connected"), "messages=$messages")
+        assertTrue(messages.any { it == "IDLE push: 1 new message(s)" }, "messages=$messages")
+        // idle() only holds host/username via ImapConnectionParams and must stay account-agnostic —
+        // attribution belongs to the IdleService caller (accountLogRef) — regression guard for #297.
+        val connectionParams = params()
+        messages.forEach { message ->
+            assertFalse(message.contains(connectionParams.host), message)
+            assertFalse(message.contains(connectionParams.username), message)
+        }
    }

    /** Creates [folderName] (holding messages) if it does not already exist. */