From 16fbf7924dc254847bc5315332157cb342c289b2 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 15 Aug 2026 12:42:06 +0000 Subject: [PATCH 1/4] Instrument the Authress login flow with timing logs and a diagnostic overlay Every Authress call now logs its duration (including the anti-abuse proof-of-work search and the network round trip separately), and the proof-of-work hash is dispatched to Dispatchers.Default so it no longer runs on the Main thread just because callers launch it from a Compose rememberCoroutineScope. Onboarding and the login screen now show a cog button that opens a scrollable, color-coded log panel backed by the existing AppLogger, so a slow or stuck sign-in can be diagnosed in place. --- .../email/data/auth/AuthressLoginClient.kt | 22 ++- .../ch/rhosys/email/data/auth/JwtManager.kt | 11 +- .../email/presentation/auth/LoginScreen.kt | 10 +- .../components/DebugLogOverlay.kt | 146 ++++++++++++++++++ .../email/presentation/navigation/NavGraph.kt | 13 +- 5 files changed, 193 insertions(+), 9 deletions(-) create mode 100644 app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt diff --git a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt index b97cd3e..c3fc274 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt @@ -127,6 +127,8 @@ class AuthressLoginClient( * once the browser has been launched; completion arrives via the deep link. */ suspend fun authenticate(options: AuthenticationOptions = AuthenticationOptions()): Result = runCatching { + val flowStartedAt = System.currentTimeMillis() + logger.info("Authress", "authenticate() started (connectionId=${options.connectionId})") _authError.value = null _authStatus.value = AuthStatus.OpeningBrowser storage.setAuthenticationRequest(null) @@ -134,6 +136,7 @@ class AuthressLoginClient( val codes = JwtManager.getAuthCodes() // Key order matches @authress/login's authenticate(): connectionId, // tenantLookupIdentifier, inviteId, applicationId, audiences. + val hashStartedAt = System.currentTimeMillis() val antiAbuseHash = JwtManager.calculateAntiAbuseHash( linkedMapOf( "connectionId" to options.connectionId, @@ -143,6 +146,7 @@ class AuthressLoginClient( "audiences" to options.audiences, ), ) + logger.info("Authress", "anti-abuse hash computed in ${System.currentTimeMillis() - hashStartedAt}ms") val body = JSONObject() .put("redirectUrl", redirectUri) .put("applicationId", BuildConfig.AUTHRESS_APPLICATION_ID) @@ -176,6 +180,7 @@ class AuthressLoginClient( withContext(Dispatchers.Main) { launchAuthenticationUrl(authenticationUrl) } + logger.info("Authress", "Custom Tab launched, ${System.currentTimeMillis() - flowStartedAt}ms since authenticate() started") _authStatus.value = AuthStatus.AwaitingRedirect }.onFailure { logger.error("Authress", "authenticate() failed", it) @@ -192,6 +197,8 @@ class AuthressLoginClient( * already redeemed. */ suspend fun completeAuthenticationRequest(uri: Uri): Result = runCatching { + val flowStartedAt = System.currentTimeMillis() + logger.info("Authress", "completeAuthenticationRequest() started (redirect received)") _authStatus.value = AuthStatus.CompletingSignIn val code = uri.getQueryParameter("code").orEmpty() val authenticationRequestId = uri.getQueryParameter("authenticationRequestId").orEmpty() @@ -204,6 +211,7 @@ class AuthressLoginClient( // Key order matches @authress/login's token exchange: client_id // (applicationId), authenticationRequestId, code. + val hashStartedAt = System.currentTimeMillis() val antiAbuseHash = JwtManager.calculateAntiAbuseHash( linkedMapOf( "applicationId" to BuildConfig.AUTHRESS_APPLICATION_ID, @@ -211,6 +219,7 @@ class AuthressLoginClient( "code" to code, ), ) + logger.info("Authress", "anti-abuse hash computed in ${System.currentTimeMillis() - hashStartedAt}ms") val body = JSONObject() .put("code", code) .put("codeVerifier", pending.codeVerifier) @@ -223,6 +232,7 @@ class AuthressLoginClient( val status = e.status if (status != null && status < 500) { // Code already used — the session is established, nothing to do. + logger.info("Authress", "token exchange returned $status, treating code as already redeemed") storage.setAuthenticationRequest(null) _sessionEstablished.value = getToken() != null _authStatus.value = AuthStatus.Idle @@ -235,6 +245,7 @@ class AuthressLoginClient( storage.setAuthenticationRequest(null) _sessionEstablished.value = getToken() != null _authStatus.value = AuthStatus.Idle + logger.info("Authress", "session established, ${System.currentTimeMillis() - flowStartedAt}ms since redirect received") }.onFailure { logger.error("Authress", "completeAuthenticationRequest() failed", it) _authStatus.value = AuthStatus.Idle @@ -286,6 +297,7 @@ class AuthressLoginClient( */ suspend fun userIsLoggedIn(): Boolean { if (getToken() != null) return true + logger.info("Authress", "userIsLoggedIn() found no cached token, refreshing via PATCH /session") return runCatching { patch("/session", JSONObject()) val loggedIn = getToken() != null @@ -431,22 +443,28 @@ class AuthressLoginClient( .header("X-Powered-By", "Authress Login SDK; Android; ${BuildConfig.VERSION_NAME}") .build() + val startedAt = System.currentTimeMillis() + logger.info("Authress", "-> ${request.method} ${request.url.encodedPath}") + val response = try { http.newCall(request).execute() } catch (e: IOException) { - logger.warn("Authress", "${request.method} ${request.url.encodedPath} network failure", e) + val elapsedMs = System.currentTimeMillis() - startedAt + logger.warn("Authress", "${request.method} ${request.url.encodedPath} network failure after ${elapsedMs}ms", e) throw e } response.use { + val elapsedMs = System.currentTimeMillis() - startedAt val text = it.body?.string().orEmpty() if (!it.isSuccessful) { - logger.warn("Authress", "${request.method} ${request.url.encodedPath} failed: ${it.code} $text") + logger.warn("Authress", "<- ${request.method} ${request.url.encodedPath} failed: ${it.code} in ${elapsedMs}ms $text") throw AuthressException( "Authress ${request.method} ${request.url.encodedPath} failed: ${it.code} $text", status = it.code, ) } + logger.info("Authress", "<- ${request.method} ${request.url.encodedPath} ${it.code} in ${elapsedMs}ms") runCatching { JSONObject(text) }.getOrDefault(JSONObject()) } } diff --git a/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt b/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt index c49a6dc..dabac9b 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt @@ -1,6 +1,8 @@ package ch.rhosys.email.data.auth import android.util.Base64 +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.withContext import org.json.JSONObject import java.security.MessageDigest import java.security.SecureRandom @@ -39,8 +41,13 @@ object JwtManager { * everything else, including lists, stringifies the way JS would when a value * falls through untouched into `Array.prototype.join('|')`: a list joins its * elements with "," (no brackets, unlike Kotlin's default `List.toString()`). + * + * This is a busy-loop search, not I/O — it's dispatched to [Dispatchers.Default] + * internally rather than left to whatever dispatcher the caller happens to be + * on, so it never runs on Main just because a caller launched from a Compose + * `rememberCoroutineScope`. */ - fun calculateAntiAbuseHash(props: Map): String { + suspend fun calculateAntiAbuseHash(props: Map): String = withContext(Dispatchers.Default) { val timestamp = System.currentTimeMillis() val valueString = props.values .filterNot { it == null || it == "" || it == false } @@ -59,7 +66,7 @@ object JwtManager { val input = "$timestamp;$fineTuner;$valueString" val digest = MessageDigest.getInstance("SHA-256").digest(input.toByteArray(Charsets.UTF_8)) val hash = Base64.encodeToString(digest, B64_URL) - if (hash.startsWith("00")) return "v2;$timestamp;$fineTuner;$hash" + if (hash.startsWith("00")) return@withContext "v2;$timestamp;$fineTuner;$hash" } } diff --git a/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt b/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt index 2338ba7..90f948e 100644 --- a/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt +++ b/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt @@ -81,8 +81,16 @@ fun LoginScreen(onSignedIn: () -> Unit) { scope.launch { mailboxLoading = true mailboxError = null + val startedAt = System.currentTimeMillis() + container.appLogger.info("Login", "Loading mailbox…") runCatching { container.accountRepository.refresh() } - .onFailure { mailboxError = it.message ?: "Couldn't load your mailbox" } + .onSuccess { + container.appLogger.info("Login", "Mailbox loaded in ${System.currentTimeMillis() - startedAt}ms") + } + .onFailure { + container.appLogger.warn("Login", "Mailbox load failed after ${System.currentTimeMillis() - startedAt}ms", it) + mailboxError = it.message ?: "Couldn't load your mailbox" + } mailboxLoading = false if (mailboxError == null) onSignedIn() } diff --git a/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt b/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt new file mode 100644 index 0000000..700380e --- /dev/null +++ b/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt @@ -0,0 +1,146 @@ +package ch.rhosys.email.presentation.components + +import android.content.ClipData +import android.content.ClipboardManager +import android.content.Context +import androidx.compose.foundation.layout.Arrangement +import androidx.compose.foundation.layout.Box +import androidx.compose.foundation.layout.Column +import androidx.compose.foundation.layout.Row +import androidx.compose.foundation.layout.fillMaxSize +import androidx.compose.foundation.layout.fillMaxWidth +import androidx.compose.foundation.layout.heightIn +import androidx.compose.foundation.layout.padding +import androidx.compose.foundation.lazy.LazyColumn +import androidx.compose.foundation.lazy.items +import androidx.compose.foundation.shape.RoundedCornerShape +import androidx.compose.material.icons.Icons +import androidx.compose.material.icons.filled.Close +import androidx.compose.material.icons.filled.Settings +import androidx.compose.material3.HorizontalDivider +import androidx.compose.material3.Icon +import androidx.compose.material3.IconButton +import androidx.compose.material3.MaterialTheme +import androidx.compose.material3.SmallFloatingActionButton +import androidx.compose.material3.Surface +import androidx.compose.material3.Text +import androidx.compose.material3.TextButton +import androidx.compose.runtime.Composable +import androidx.compose.runtime.collectAsState +import androidx.compose.runtime.getValue +import androidx.compose.runtime.mutableStateOf +import androidx.compose.runtime.remember +import androidx.compose.runtime.rememberCoroutineScope +import androidx.compose.ui.Alignment +import androidx.compose.ui.Modifier +import androidx.compose.ui.platform.LocalContext +import androidx.compose.ui.text.font.FontFamily +import androidx.compose.ui.unit.dp +import ch.rhosys.email.data.local.entity.LogEntryEntity +import ch.rhosys.email.data.log.AppLogger +import kotlinx.coroutines.launch +import java.text.SimpleDateFormat +import java.util.Date +import java.util.Locale + +/** + * Wraps [content] with a persistent cog button in the bottom-right corner + * that opens a scrollable diagnostic-log panel — the same entries visible in + * Settings > Logs, but reachable before a session (or a mailbox) exists, so a + * slow or failed sign-in can be inspected without leaving the screen. + */ +@Composable +fun DebugLogOverlay(logger: AppLogger, modifier: Modifier = Modifier, content: @Composable () -> Unit) { + var expanded by remember { mutableStateOf(false) } + val logs by logger.observeAll().collectAsState(initial = emptyList()) + val scope = rememberCoroutineScope() + + Box(modifier = modifier.fillMaxSize()) { + content() + + if (expanded) { + LogPanel( + logs = logs, + onClose = { expanded = false }, + onClear = { scope.launch { logger.clear() } }, + modifier = Modifier.align(Alignment.BottomCenter), + ) + } + + SmallFloatingActionButton( + onClick = { expanded = !expanded }, + modifier = Modifier.align(Alignment.BottomEnd).padding(16.dp), + ) { + Icon(Icons.Filled.Settings, contentDescription = "Diagnostic logs") + } + } +} + +@Composable +private fun LogPanel(logs: List, onClose: () -> Unit, onClear: () -> Unit, modifier: Modifier = Modifier) { + val context = LocalContext.current + Surface( + color = MaterialTheme.colorScheme.surfaceVariant, + shape = RoundedCornerShape(topStart = 16.dp, topEnd = 16.dp), + tonalElevation = 4.dp, + modifier = modifier.fillMaxWidth().heightIn(max = 320.dp), + ) { + Column(modifier = Modifier.padding(12.dp)) { + Row( + modifier = Modifier.fillMaxWidth(), + horizontalArrangement = Arrangement.SpaceBetween, + verticalAlignment = Alignment.CenterVertically, + ) { + Text("Diagnostic logs", style = MaterialTheme.typography.titleSmall) + Row(verticalAlignment = Alignment.CenterVertically) { + TextButton(enabled = logs.isNotEmpty(), onClick = { copyToClipboard(context, logs) }) { Text("Copy") } + TextButton(enabled = logs.isNotEmpty(), onClick = onClear) { Text("Clear") } + IconButton(onClick = onClose) { + Icon(Icons.Filled.Close, contentDescription = "Close") + } + } + } + HorizontalDivider(modifier = Modifier.padding(vertical = 4.dp)) + if (logs.isEmpty()) { + Text( + "No logs yet.", + style = MaterialTheme.typography.bodySmall, + color = MaterialTheme.colorScheme.onSurfaceVariant, + modifier = Modifier.padding(vertical = 8.dp), + ) + } else { + // logs is newest-first (id DESC); reverseLayout renders index 0 at the + // bottom, so the panel opens already scrolled to the most recent entry. + LazyColumn(reverseLayout = true, modifier = Modifier.fillMaxWidth()) { + items(logs, key = { it.id }) { entry -> + Text( + text = entry.toLogLine(), + style = MaterialTheme.typography.bodySmall, + fontFamily = FontFamily.Monospace, + color = entry.levelColor(), + modifier = Modifier.padding(vertical = 2.dp), + ) + } + } + } + } + } +} + +@Composable +private fun LogEntryEntity.levelColor() = when (level) { + "ERROR" -> MaterialTheme.colorScheme.error + "WARN" -> MaterialTheme.colorScheme.tertiary + else -> MaterialTheme.colorScheme.onSurfaceVariant +} + +private fun copyToClipboard(context: Context, logs: List) { + val text = logs.reversed().joinToString("\n") { it.toLogLine() } + val clipboard = context.getSystemService(Context.CLIPBOARD_SERVICE) as ClipboardManager + clipboard.setPrimaryClip(ClipData.newPlainText("Diagnostic logs", text)) +} + +private val timeFormatter = SimpleDateFormat("HH:mm:ss.SSS", Locale.getDefault()) + +private fun LogEntryEntity.toLogLine(): String = + "${timeFormatter.format(Date(timestamp))} [$level] $tag: $message" diff --git a/app/src/main/java/ch/rhosys/email/presentation/navigation/NavGraph.kt b/app/src/main/java/ch/rhosys/email/presentation/navigation/NavGraph.kt index bfb3638..20100de 100644 --- a/app/src/main/java/ch/rhosys/email/presentation/navigation/NavGraph.kt +++ b/app/src/main/java/ch/rhosys/email/presentation/navigation/NavGraph.kt @@ -17,6 +17,7 @@ import androidx.navigation.navArgument import ch.rhosys.email.di.LocalAppContainer import ch.rhosys.email.presentation.auth.LoginScreen import ch.rhosys.email.presentation.changelog.ChangelogDialog +import ch.rhosys.email.presentation.components.DebugLogOverlay import ch.rhosys.email.presentation.compose.ComposeScreen import ch.rhosys.email.presentation.drafts.DraftsScreen import ch.rhosys.email.presentation.inbox.InboxScreen @@ -49,10 +50,14 @@ fun RootNavGraph() { when (gate) { RootGate.LOADING -> CircularProgressIndicator() - RootGate.ONBOARDING -> OnboardingScreen(onFinished = { - gate = if (container.authManager.isSignedIn) RootGate.APP else RootGate.LOGIN - }) - RootGate.LOGIN -> LoginScreen(onSignedIn = { gate = RootGate.APP }) + RootGate.ONBOARDING -> DebugLogOverlay(container.appLogger) { + OnboardingScreen(onFinished = { + gate = if (container.authManager.isSignedIn) RootGate.APP else RootGate.LOGIN + }) + } + RootGate.LOGIN -> DebugLogOverlay(container.appLogger) { + LoginScreen(onSignedIn = { gate = RootGate.APP }) + } RootGate.APP -> { ChangelogDialog(container.preferencesStore) FeatureTourDialog(container.preferencesStore) From a6b15e08575cd8017f84067344b3a5b051157457 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 15 Aug 2026 13:10:28 +0000 Subject: [PATCH 2/4] Fix CI compile errors, break Authress interceptor self-block, widen logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - CI caught two real compile errors from the previous commit: the anti-abuse hash's suspend/withContext refactor inferred Unit instead of String, and DebugLogOverlay was missing the setValue operator import for its `var expanded by remember {...}`. Both fixed. - Found and fixed a real bug while adding request timing: AuthressLoginClient was built from the same OkHttpClient as the Email API, which carries AuthInterceptor. That interceptor waits on waitForToken() — before a session exists, every unauthenticated Authress call (including the very POST /authentication that starts login) blocked for its full 5s timeout waiting for a session that only that same call could establish. Authress now gets its own client without AuthInterceptor. - Logging now covers more than the login path: ApiLoggingInterceptor gives the Email API the same production-visible request timing Authress calls already had (HttpLoggingInterceptor is debug-only), and ThreadRepository's syncPending/SyncForegroundService — previously silent — now log queue sizes, per-item failures, and tick duration. - authenticate()/completeAuthenticationRequest() split into more granular AuthStatus/LoginStep stages (RequestingAuthenticationUrl, OpeningBrowser, AwaitingRedirect, VerifyingRedirect, ExchangingToken) so the sign-in checklist shows which specific call is slow instead of one wide phase. - Diagnosed "authentication request mismatch": tapping "Try again" while an earlier Custom Tab is still alive starts a second attempt: the old tab can still redirect back with the old authenticationRequestId after storage has moved on to the new one. authenticate() now logs when it abandons a live attempt, and the mismatch log line names both the pending and redirect IDs so the two can be correlated instead of the mismatch looking unexplained. --- .../main/java/ch/rhosys/email/MainActivity.kt | 9 ++- .../email/data/auth/AuthressLoginClient.kt | 71 ++++++++++++++++--- .../ch/rhosys/email/data/auth/JwtManager.kt | 7 +- .../data/remote/api/ApiLoggingInterceptor.kt | 39 ++++++++++ .../data/remote/api/UserAgentInterceptor.kt | 7 +- .../data/repository/ThreadRepositoryImpl.kt | 31 +++++++- .../java/ch/rhosys/email/di/AppContainer.kt | 32 +++++++-- .../email/presentation/auth/LoginScreen.kt | 10 ++- .../components/DebugLogOverlay.kt | 1 + .../email/sync/SyncForegroundService.kt | 4 ++ 10 files changed, 185 insertions(+), 26 deletions(-) create mode 100644 app/src/main/java/ch/rhosys/email/data/remote/api/ApiLoggingInterceptor.kt diff --git a/app/src/main/java/ch/rhosys/email/MainActivity.kt b/app/src/main/java/ch/rhosys/email/MainActivity.kt index f1be306..b02f058 100644 --- a/app/src/main/java/ch/rhosys/email/MainActivity.kt +++ b/app/src/main/java/ch/rhosys/email/MainActivity.kt @@ -64,7 +64,14 @@ class MainActivity : FragmentActivity() { private fun handleAuthRedirect(intent: Intent?) { val appContainer = (application as EmailApp).appContainer val uri = intent?.data ?: return - if (!appContainer.authManager.isRedirect(uri)) return + val isRedirect = appContainer.authManager.isRedirect(uri) + // Not the auth code itself — just scheme/host/path — so this is safe to log + // even when it turns out not to be an Authress redirect at all. + appContainer.appLogger.info( + "Authress", + "handleAuthRedirect: received ${uri.scheme}://${uri.host}${uri.path}, isRedirect=$isRedirect", + ) + if (!isRedirect) return lifecycleScope.launch { appContainer.authManager.completeAuthenticationRequest(uri) } } diff --git a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt index c3fc274..9ac550e 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt @@ -81,10 +81,22 @@ class AuthressLoginClient( * slow instead of a single spinner covering everything from "tapped * Continue" to "mailbox loaded". [AwaitingRedirect] can legitimately sit * for a while (the user is doing something in the browser); the others - * are calls to Authress and are worth a "this is taking a while" hint if - * they don't resolve quickly. + * are calls to Authress (or local validation) and are worth a "this is + * taking a while" hint if they don't resolve quickly. + * + * Split finer than a single "signing in" spinner on purpose: each of these + * is a distinct network call or check, and a user stuck on, say, + * [ExchangingToken] for 30s is showing us something different than one + * stuck on [RequestingAuthenticationUrl]. */ - enum class AuthStatus { Idle, OpeningBrowser, AwaitingRedirect, CompletingSignIn } + enum class AuthStatus { + Idle, + RequestingAuthenticationUrl, + OpeningBrowser, + AwaitingRedirect, + VerifyingRedirect, + ExchangingToken, + } private val _authStatus = MutableStateFlow(AuthStatus.Idle) val authStatus: StateFlow = _authStatus.asStateFlow() @@ -128,9 +140,26 @@ class AuthressLoginClient( */ suspend fun authenticate(options: AuthenticationOptions = AuthenticationOptions()): Result = runCatching { val flowStartedAt = System.currentTimeMillis() + + val previousStatus = _authStatus.value + val abandonedPending = storage.getAuthenticationRequest() + if (previousStatus != AuthStatus.Idle) { + // Most often: the user waited past the slow-hint and tapped "Try again" + // while the first Custom Tab is still alive. That tab can still redirect + // back with the OLD authenticationRequestId after we've moved on to a + // new one — completeAuthenticationRequest() will log that as a mismatch + // against the new pending request. Logged here so the two log lines can + // be correlated instead of the mismatch looking unexplained. + logger.warn( + "Authress", + "authenticate() re-entered while previous attempt was $previousStatus" + + (abandonedPending?.let { " — abandoning authenticationRequestId=${it.authenticationRequestId}" } ?: ""), + ) + } + logger.info("Authress", "authenticate() started (connectionId=${options.connectionId})") _authError.value = null - _authStatus.value = AuthStatus.OpeningBrowser + _authStatus.value = AuthStatus.RequestingAuthenticationUrl storage.setAuthenticationRequest(null) val codes = JwtManager.getAuthCodes() @@ -146,7 +175,7 @@ class AuthressLoginClient( "audiences" to options.audiences, ), ) - logger.info("Authress", "anti-abuse hash computed in ${System.currentTimeMillis() - hashStartedAt}ms") + logAntiAbuseHash(antiAbuseHash, System.currentTimeMillis() - hashStartedAt) val body = JSONObject() .put("redirectUrl", redirectUri) .put("applicationId", BuildConfig.AUTHRESS_APPLICATION_ID) @@ -168,6 +197,7 @@ class AuthressLoginClient( val response = post("/authentication", body) val authenticationUrl = response.getString("authenticationUrl") val authenticationRequestId = response.getString("authenticationRequestId") + logger.info("Authress", "authentication request created: authenticationRequestId=$authenticationRequestId") storage.setAuthenticationRequest( AuthStorageManager.PendingAuthentication( @@ -177,6 +207,7 @@ class AuthressLoginClient( ), ) + _authStatus.value = AuthStatus.OpeningBrowser withContext(Dispatchers.Main) { launchAuthenticationUrl(authenticationUrl) } @@ -198,19 +229,31 @@ class AuthressLoginClient( */ suspend fun completeAuthenticationRequest(uri: Uri): Result = runCatching { val flowStartedAt = System.currentTimeMillis() - logger.info("Authress", "completeAuthenticationRequest() started (redirect received)") - _authStatus.value = AuthStatus.CompletingSignIn val code = uri.getQueryParameter("code").orEmpty() val authenticationRequestId = uri.getQueryParameter("authenticationRequestId").orEmpty() + logger.info( + "Authress", + "completeAuthenticationRequest() started (redirect received, authenticationRequestId=$authenticationRequestId, " + + "code=${if (code.isEmpty()) "missing" else "present"})", + ) + _authStatus.value = AuthStatus.VerifyingRedirect val pending = storage.getAuthenticationRequest() - ?: throw AuthressException("No authentication request in progress") + ?: throw AuthressException("No authentication request in progress (redirect carried authenticationRequestId=$authenticationRequestId)") if (pending.authenticationRequestId != authenticationRequestId) { + // The likely cause is logged by authenticate() when it abandons a + // still-live attempt; these two lines are meant to be read together. + logger.warn( + "Authress", + "authentication request mismatch: pending=${pending.authenticationRequestId}, redirect=$authenticationRequestId " + + "— this redirect is probably from an earlier Custom Tab that was still open when a new attempt started", + ) throw AuthressException("Authentication request mismatch") } // Key order matches @authress/login's token exchange: client_id // (applicationId), authenticationRequestId, code. + _authStatus.value = AuthStatus.ExchangingToken val hashStartedAt = System.currentTimeMillis() val antiAbuseHash = JwtManager.calculateAntiAbuseHash( linkedMapOf( @@ -219,7 +262,7 @@ class AuthressLoginClient( "code" to code, ), ) - logger.info("Authress", "anti-abuse hash computed in ${System.currentTimeMillis() - hashStartedAt}ms") + logAntiAbuseHash(antiAbuseHash, System.currentTimeMillis() - hashStartedAt) val body = JSONObject() .put("code", code) .put("codeVerifier", pending.codeVerifier) @@ -437,6 +480,16 @@ class AuthressLoginClient( private fun JSONObject.toBody() = toString().toRequestBody(JSON) + /** + * The hash is `v2;timestamp;fineTuner;hash` — fineTuner is the proof-of-work + * iteration count, the concrete number that tells us whether a slow sign-in is + * this device's CPU grinding through the search versus network/browser time. + */ + private fun logAntiAbuseHash(antiAbuseHash: String, elapsedMs: Long) { + val iterations = antiAbuseHash.split(";").getOrNull(2) ?: "?" + logger.info("Authress", "anti-abuse hash computed in ${elapsedMs}ms ($iterations iterations)") + } + private suspend fun execute(builder: Request.Builder): JSONObject = withContext(Dispatchers.IO) { val request = builder .header("Content-Type", "application/json") diff --git a/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt b/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt index dabac9b..702f536 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/JwtManager.kt @@ -47,7 +47,10 @@ object JwtManager { * on, so it never runs on Main just because a caller launched from a Compose * `rememberCoroutineScope`. */ - suspend fun calculateAntiAbuseHash(props: Map): String = withContext(Dispatchers.Default) { + suspend fun calculateAntiAbuseHash(props: Map): String = + withContext(Dispatchers.Default) { searchAntiAbuseHash(props) } + + private fun searchAntiAbuseHash(props: Map): String { val timestamp = System.currentTimeMillis() val valueString = props.values .filterNot { it == null || it == "" || it == false } @@ -66,7 +69,7 @@ object JwtManager { val input = "$timestamp;$fineTuner;$valueString" val digest = MessageDigest.getInstance("SHA-256").digest(input.toByteArray(Charsets.UTF_8)) val hash = Base64.encodeToString(digest, B64_URL) - if (hash.startsWith("00")) return@withContext "v2;$timestamp;$fineTuner;$hash" + if (hash.startsWith("00")) return "v2;$timestamp;$fineTuner;$hash" } } diff --git a/app/src/main/java/ch/rhosys/email/data/remote/api/ApiLoggingInterceptor.kt b/app/src/main/java/ch/rhosys/email/data/remote/api/ApiLoggingInterceptor.kt new file mode 100644 index 0000000..07ef9b9 --- /dev/null +++ b/app/src/main/java/ch/rhosys/email/data/remote/api/ApiLoggingInterceptor.kt @@ -0,0 +1,39 @@ +package ch.rhosys.email.data.remote.api + +import ch.rhosys.email.data.log.AppLogger +import okhttp3.Interceptor +import okhttp3.Response +import java.io.IOException + +/** + * Logs every request through the shared OkHttpClient — method, path, status, + * duration, and response size — to [AppLogger]. `HttpLoggingInterceptor` only + * runs in debug builds; this is the production-visible equivalent, so a slow + * or failing Email API call (mailbox load, sync, etc.) shows up in the same + * log a user can review in Settings > Logs or the onboarding/login overlay, + * not just Authress calls. + */ +class ApiLoggingInterceptor(private val logger: AppLogger) : Interceptor { + override fun intercept(chain: Interceptor.Chain): Response { + val request = chain.request() + val startedAt = System.currentTimeMillis() + + val response = try { + chain.proceed(request) + } catch (e: IOException) { + val elapsedMs = System.currentTimeMillis() - startedAt + logger.warn("Api", "${request.method} ${request.url.encodedPath} network failure after ${elapsedMs}ms", e) + throw e + } + + val elapsedMs = System.currentTimeMillis() - startedAt + val contentLength = response.body?.contentLength()?.takeIf { it >= 0 } + val sizeSuffix = contentLength?.let { ", ${it}B" }.orEmpty() + if (!response.isSuccessful) { + logger.warn("Api", "${request.method} ${request.url.encodedPath} failed: ${response.code} in ${elapsedMs}ms$sizeSuffix") + } else { + logger.info("Api", "${request.method} ${request.url.encodedPath} -> ${response.code} in ${elapsedMs}ms$sizeSuffix") + } + return response + } +} diff --git a/app/src/main/java/ch/rhosys/email/data/remote/api/UserAgentInterceptor.kt b/app/src/main/java/ch/rhosys/email/data/remote/api/UserAgentInterceptor.kt index c45ad96..d050bfe 100644 --- a/app/src/main/java/ch/rhosys/email/data/remote/api/UserAgentInterceptor.kt +++ b/app/src/main/java/ch/rhosys/email/data/remote/api/UserAgentInterceptor.kt @@ -5,10 +5,9 @@ import okhttp3.Interceptor import okhttp3.Response /** - * Stamps a real User-Agent on every request. Installed on the shared - * OkHttpClient in [ch.rhosys.email.di.AppContainer], so it covers both the - * Email API calls and the Authress session calls (whose client is built off - * the same instance) instead of leaving OkHttp's default `okhttp/`. + * Stamps a real User-Agent on every request. Installed on both OkHttpClients + * built in [ch.rhosys.email.di.AppContainer] — the Email API client and the + * Authress-only client — instead of leaving OkHttp's default `okhttp/`. */ class UserAgentInterceptor : Interceptor { override fun intercept(chain: Interceptor.Chain): Response { diff --git a/app/src/main/java/ch/rhosys/email/data/repository/ThreadRepositoryImpl.kt b/app/src/main/java/ch/rhosys/email/data/repository/ThreadRepositoryImpl.kt index 617355a..4506b58 100644 --- a/app/src/main/java/ch/rhosys/email/data/repository/ThreadRepositoryImpl.kt +++ b/app/src/main/java/ch/rhosys/email/data/repository/ThreadRepositoryImpl.kt @@ -8,6 +8,7 @@ import androidx.paging.map import ch.rhosys.email.data.local.EmailDatabase import ch.rhosys.email.data.local.entity.toDomain import ch.rhosys.email.data.local.entity.toEntity +import ch.rhosys.email.data.log.AppLogger import ch.rhosys.email.data.remote.api.EmailApiService import ch.rhosys.email.data.remote.dto.PatchThreadRequest import ch.rhosys.email.data.remote.dto.QuarantineResponseRequest @@ -33,6 +34,7 @@ import java.time.Instant class ThreadRepositoryImpl( private val api: EmailApiService, private val db: EmailDatabase, + private val logger: AppLogger, ) : ThreadRepository { private val threadDao = db.threadDao() @@ -118,7 +120,15 @@ class ThreadRepositoryImpl( } override suspend fun syncPending() { - threadDao.pendingSync().forEach { entity -> + val pendingThreads = threadDao.pendingSync() + val pendingSignals = signalDao.pendingSync() + if (pendingThreads.isEmpty() && pendingSignals.isEmpty()) return + + val startedAt = System.currentTimeMillis() + logger.info("Sync", "syncPending: ${pendingThreads.size} thread(s), ${pendingSignals.size} signal(s) queued") + + var threadFailures = 0 + pendingThreads.forEach { entity -> runCatching { api.patchThread( entity.accountId, @@ -130,18 +140,33 @@ class ThreadRepositoryImpl( ), ) threadDao.update(entity.copy(isPendingSync = false)) + }.onFailure { + threadFailures++ + logger.warn("Sync", "syncPending: thread ${entity.threadId} failed", it) } } - signalDao.pendingSync().forEach { entity -> + + var signalFailures = 0 + pendingSignals.forEach { entity -> + val threadId = entity.threadId ?: return@forEach runCatching { api.patchSignal( entity.accountId, - entity.threadId ?: return@runCatching, + threadId, entity.signalId, ch.rhosys.email.data.remote.dto.PatchSignalRequest(entity.status), ) signalDao.updateStatus(entity.signalId, entity.status, pending = false) + }.onFailure { + signalFailures++ + logger.warn("Sync", "syncPending: signal ${entity.signalId} failed", it) } } + + logger.info( + "Sync", + "syncPending finished in ${System.currentTimeMillis() - startedAt}ms " + + "($threadFailures/${pendingThreads.size} thread failures, $signalFailures/${pendingSignals.size} signal failures)", + ) } } diff --git a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt index 750bfa2..228dd64 100644 --- a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt +++ b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt @@ -8,6 +8,7 @@ import ch.rhosys.email.data.auth.AuthressLoginClient import ch.rhosys.email.data.auth.TokenStore import ch.rhosys.email.data.local.EmailDatabase import ch.rhosys.email.data.log.AppLogger +import ch.rhosys.email.data.remote.api.ApiLoggingInterceptor import ch.rhosys.email.data.remote.api.AuthInterceptor import ch.rhosys.email.data.remote.api.EmailApiService import ch.rhosys.email.data.remote.api.UserAgentInterceptor @@ -54,7 +55,7 @@ class AppContainer(private val context: Context) { } val authManager: AuthressLoginClient by lazy { - AuthressLoginClient(context, cookieJar, okHttpClient, appLogger) + AuthressLoginClient(context, cookieJar, authHttpClient, appLogger) } private val moshi: Moshi by lazy { @@ -65,17 +66,38 @@ class AppContainer(private val context: Context) { .build() } - private val okHttpClient: OkHttpClient by lazy { + /** + * Authress's own calls must never go through [AuthInterceptor]: that interceptor + * calls [AuthressLoginClient.waitForToken], which — before a session exists — + * blocks for its full 5s timeout waiting for a session that can only be + * established by the very call being made. Wiring `authManager` off the same + * client as `okHttpClient` (which carries [AuthInterceptor]) previously did + * exactly that: every unauthenticated Authress call, including the initial + * `POST /authentication` that starts login, stalled 5s before the request even + * went out. This client carries the identifying headers but not the bearer-auth + * interceptor, since Authress sessions live in cookies, not a bearer token. + */ + private val authHttpClient: OkHttpClient by lazy { + // No debug HttpLoggingInterceptor here: AuthressLoginClient.execute() already + // logs method/path/status/duration through AppLogger for every Authress call, + // in both debug and release, making it redundant. OkHttpClient.Builder() .addInterceptor(UserAgentInterceptor()) + .connectTimeout(30, TimeUnit.SECONDS) + .readTimeout(30, TimeUnit.SECONDS) + .build() + } + + /** For the Email API only. Adds bearer auth and the same timing-log visibility Authress calls get, plus debug body logging. */ + private val okHttpClient: OkHttpClient by lazy { + authHttpClient.newBuilder() .addInterceptor(AuthInterceptor { authManager.waitForToken() }) + .addInterceptor(ApiLoggingInterceptor(appLogger)) .apply { if (BuildConfig.DEBUG) { addInterceptor(HttpLoggingInterceptor().setLevel(HttpLoggingInterceptor.Level.BASIC)) } } - .connectTimeout(30, TimeUnit.SECONDS) - .readTimeout(30, TimeUnit.SECONDS) .build() } @@ -101,7 +123,7 @@ class AppContainer(private val context: Context) { } val threadRepository: ThreadRepository by lazy { - ThreadRepositoryImpl(apiService, database) + ThreadRepositoryImpl(apiService, database, appLogger) } val composeRepository: ComposeRepository by lazy { diff --git a/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt b/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt index 90f948e..3da8b40 100644 --- a/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt +++ b/app/src/main/java/ch/rhosys/email/presentation/auth/LoginScreen.kt @@ -39,9 +39,11 @@ import kotlinx.coroutines.launch * *where* it's stuck rather than just that "something" is loading. */ private enum class LoginStep(val label: String) { + RequestingAuthenticationUrl("Requesting the sign-in page"), OpeningBrowser("Opening the sign-in page"), AwaitingRedirect("Waiting for you to finish in the browser"), - CompletingSignIn("Completing sign-in"), + VerifyingRedirect("Verifying the sign-in response"), + ExchangingToken("Completing sign-in"), LoadingMailbox("Loading your mailbox"), } @@ -71,9 +73,11 @@ fun LoginScreen(onSignedIn: () -> Unit) { val currentStep = when { mailboxLoading -> LoginStep.LoadingMailbox + authStatus == AuthressLoginClient.AuthStatus.RequestingAuthenticationUrl -> LoginStep.RequestingAuthenticationUrl authStatus == AuthressLoginClient.AuthStatus.OpeningBrowser -> LoginStep.OpeningBrowser authStatus == AuthressLoginClient.AuthStatus.AwaitingRedirect -> LoginStep.AwaitingRedirect - authStatus == AuthressLoginClient.AuthStatus.CompletingSignIn -> LoginStep.CompletingSignIn + authStatus == AuthressLoginClient.AuthStatus.VerifyingRedirect -> LoginStep.VerifyingRedirect + authStatus == AuthressLoginClient.AuthStatus.ExchangingToken -> LoginStep.ExchangingToken else -> null } @@ -122,6 +126,7 @@ fun LoginScreen(onSignedIn: () -> Unit) { if (currentStep == null) { Button(onClick = { + container.appLogger.info("Login", "\"Continue\" tapped") mailboxError = null scope.launch { container.authManager.authenticate() } }) { @@ -140,6 +145,7 @@ fun LoginScreen(onSignedIn: () -> Unit) { modifier = Modifier.padding(top = 16.dp), ) TextButton(onClick = { + container.appLogger.info("Login", "\"Try again\" tapped while stuck on $currentStep") if (currentStep == LoginStep.LoadingMailbox) loadMailbox() else { mailboxError = null scope.launch { container.authManager.authenticate() } diff --git a/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt b/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt index 700380e..a760f02 100644 --- a/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt +++ b/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt @@ -31,6 +31,7 @@ import androidx.compose.runtime.getValue import androidx.compose.runtime.mutableStateOf import androidx.compose.runtime.remember import androidx.compose.runtime.rememberCoroutineScope +import androidx.compose.runtime.setValue import androidx.compose.ui.Alignment import androidx.compose.ui.Modifier import androidx.compose.ui.platform.LocalContext diff --git a/app/src/main/java/ch/rhosys/email/sync/SyncForegroundService.kt b/app/src/main/java/ch/rhosys/email/sync/SyncForegroundService.kt index 90911dc..55f4514 100644 --- a/app/src/main/java/ch/rhosys/email/sync/SyncForegroundService.kt +++ b/app/src/main/java/ch/rhosys/email/sync/SyncForegroundService.kt @@ -34,9 +34,11 @@ class SyncForegroundService : Service() { super.onCreate() startForeground(NOTIFICATION_ID, buildNotification()) val container = (application as? ch.rhosys.email.EmailApp)?.appContainer ?: return + container.appLogger.info("Sync", "SyncForegroundService started, interval ${SYNC_INTERVAL_MS}ms") syncJob = scope.launch { while (true) { runCatching { container.threadRepository.syncPending() } + .onFailure { container.appLogger.warn("Sync", "syncPending tick crashed", it) } delay(SYNC_INTERVAL_MS) } } @@ -59,6 +61,8 @@ class SyncForegroundService : Service() { override fun onBind(intent: Intent?): IBinder? = null override fun onDestroy() { + val container = (application as? ch.rhosys.email.EmailApp)?.appContainer + container?.appLogger?.info("Sync", "SyncForegroundService stopped") scope.cancel() super.onDestroy() } From c60121134eb9e797c30308a3d5cb394d3ab3ff9f Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 15 Aug 2026 13:18:19 +0000 Subject: [PATCH 3/4] Make AuthInterceptor non-blocking instead of runBlocking-waiting for a token MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit AuthInterceptor ran on OkHttp's dispatcher pool for every Email API request and used runBlocking to await AuthressLoginClient.waitForToken() there. That mixes concerns: waiting for a browser-driven login the request has nothing to do with is a foreground/UI concern, not something a background request-attachment interceptor should block a pool thread on. It's also exactly what caused the earlier 5s stall bug (a request racing an in-progress login could block behind an unrelated flow). AuthInterceptor now takes a synchronous, non-suspending token provider and attaches whatever token is cached right now via getToken() — never waits. waitForToken() stays available for a foreground caller that deliberately wants to gate on sign-in (the login screen), which is the only place it should ever be awaited from. --- .../email/data/auth/AuthressLoginClient.kt | 11 +++++--- .../email/data/remote/api/AuthInterceptor.kt | 25 +++++++++++-------- .../java/ch/rhosys/email/di/AppContainer.kt | 20 +++++++-------- todo.md | 8 ++++-- 4 files changed, 38 insertions(+), 26 deletions(-) diff --git a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt index 9ac550e..faf4207 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt @@ -350,11 +350,16 @@ class AuthressLoginClient( } /** - * Waits until a bearer token is available, then returns it. Blocks until + * Waits until a bearer token is available, then returns it. Suspends until * [authenticate] plus [completeAuthenticationRequest], or [userIsLoggedIn], * establishes a session. This is the SDK's documented way to obtain the value - * for an Authorization header, and is what [ch.rhosys.email.data.remote.api.AuthInterceptor] - * uses — reading the cookie directly would race a session that is mid-refresh. + * for an Authorization header — but only for a foreground, UI-driven caller + * that is deliberately gating on sign-in (e.g. the login screen itself). It is + * NOT for [ch.rhosys.email.data.remote.api.AuthInterceptor], which attaches + * whatever token is cached right now and never blocks: that interceptor runs + * on OkHttp's own dispatcher for every request, and blocking one of its + * threads on a browser-driven login the request has nothing to do with is + * exactly the kind of stall this class exists to avoid. * * Returns null if no token arrives within [timeoutInMillis]; 0 means do not * wait at all, matching the SDK. diff --git a/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt b/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt index 9e77785..87bdb82 100644 --- a/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt +++ b/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt @@ -1,23 +1,28 @@ package ch.rhosys.email.data.remote.api -import kotlinx.coroutines.runBlocking import okhttp3.Interceptor import okhttp3.Response /** * Attaches the Authress session token to API calls. * - * The token comes from the login client's waitForToken, which is what the SDK - * documents for an Authorization header: it returns immediately when a valid - * session exists, and otherwise waits briefly for one being established rather - * than firing a request that is certain to be rejected. - * - * runBlocking is safe here — OkHttp interceptors already run on a background - * dispatcher, never the main thread. + * Deliberately synchronous and non-blocking: [tokenProvider] reads whatever + * token is cached right now (see [ch.rhosys.email.data.auth.AuthressLoginClient.getToken]) + * and nothing more. This interceptor runs on OkHttp's dispatcher for every + * request — it is not the right place to await a session that only a + * foreground, user-driven flow (the login screen, waiting on the browser) can + * establish. An earlier version called the suspend `waitForToken()` here via + * `runBlocking`, which meant an ordinary API call could sit blocked on a pool + * thread for its full timeout waiting on unrelated browser-driven login — + * exactly the kind of stall this class exists to attach a token quickly, not + * cause. If no token is cached, the request goes out without one and the + * caller sees the resulting 401 like any other API error; ensuring a session + * is ready is [ch.rhosys.email.presentation.navigation.AppNavHost]'s job via + * `userIsLoggedIn()`, not this interceptor's. */ -class AuthInterceptor(private val tokenProvider: suspend () -> String?) : Interceptor { +class AuthInterceptor(private val tokenProvider: () -> String?) : Interceptor { override fun intercept(chain: Interceptor.Chain): Response { - val token = runBlocking { tokenProvider() } + val token = tokenProvider() val request = chain.request().newBuilder().apply { if (token != null) addHeader("Authorization", "Bearer $token") }.build() diff --git a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt index 228dd64..15ef504 100644 --- a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt +++ b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt @@ -67,15 +67,9 @@ class AppContainer(private val context: Context) { } /** - * Authress's own calls must never go through [AuthInterceptor]: that interceptor - * calls [AuthressLoginClient.waitForToken], which — before a session exists — - * blocks for its full 5s timeout waiting for a session that can only be - * established by the very call being made. Wiring `authManager` off the same - * client as `okHttpClient` (which carries [AuthInterceptor]) previously did - * exactly that: every unauthenticated Authress call, including the initial - * `POST /authentication` that starts login, stalled 5s before the request even - * went out. This client carries the identifying headers but not the bearer-auth - * interceptor, since Authress sessions live in cookies, not a bearer token. + * Authress's own calls must never carry [AuthInterceptor]: Authress sessions + * live in cookies, not a bearer token, so the interceptor has nothing to add + * there — it exists for the Email API client below. */ private val authHttpClient: OkHttpClient by lazy { // No debug HttpLoggingInterceptor here: AuthressLoginClient.execute() already @@ -88,10 +82,14 @@ class AppContainer(private val context: Context) { .build() } - /** For the Email API only. Adds bearer auth and the same timing-log visibility Authress calls get, plus debug body logging. */ + /** + * For the Email API only. Adds bearer auth (from whatever token is cached right + * now — see [AuthInterceptor], deliberately non-blocking) and the same + * timing-log visibility Authress calls get, plus debug body logging. + */ private val okHttpClient: OkHttpClient by lazy { authHttpClient.newBuilder() - .addInterceptor(AuthInterceptor { authManager.waitForToken() }) + .addInterceptor(AuthInterceptor { authManager.getToken() }) .addInterceptor(ApiLoggingInterceptor(appLogger)) .apply { if (BuildConfig.DEBUG) { diff --git a/todo.md b/todo.md index a78bfd7..a942f57 100644 --- a/todo.md +++ b/todo.md @@ -26,8 +26,12 @@ POST /api/authentication/{id}/tokens -> session cookies The session lives in the `authorization` and `user` cookies rather than an access/refresh pair. `userIsLoggedIn()` refreshes it via `PATCH /session` and is -called on every route change, per the SDK's own recommendation; `waitForToken()` -supplies the Authorization header. +called on every route change, per the SDK's own recommendation. `AuthInterceptor` +attaches whatever token is cached synchronously and never blocks a request on it; +`waitForToken()` is only for a foreground caller deliberately gating on sign-in +(the login screen) — an interceptor that `runBlocking`'d it used to stall every +Email API call for up to 5s whenever no session existed yet, which was also why +the very first Authress call of a fresh login was stalling. The duplicate redirect claim is gone with AppAuth: MainActivity is now the only component matching the scheme, and it forwards the redirect through From 7adaab2b55a6abb7a0fabcb88620458729ef753b Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 15 Aug 2026 13:41:51 +0000 Subject: [PATCH 4/4] Restore waitForToken() as AuthInterceptor's token source MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Walking back the previous commit's change to a synchronous, non-waiting AuthInterceptor: waitForToken() belongs exactly there — it's the HTTP call wrapper grabbing a token right before an Email API request goes out, which is the one legitimate caller for it. That's safe (runBlocking inside an OkHttp interceptor never touches the main thread) specifically because Authress's own client (authHttpClient) never carries this interceptor — that split, not removing the wait, is what actually fixed the earlier 5s stall bug (POST /authentication waiting on a session only it could create). No other caller for waitForToken() exists or should; doc comments on it, AuthInterceptor, and AppContainer now say so directly instead of describing a foreground caller that was never wired up. --- .../email/data/auth/AuthressLoginClient.kt | 13 ++++---- .../email/data/remote/api/AuthInterceptor.kt | 33 ++++++++++--------- .../java/ch/rhosys/email/di/AppContainer.kt | 8 ++--- todo.md | 15 +++++---- 4 files changed, 36 insertions(+), 33 deletions(-) diff --git a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt index faf4207..fc95ede 100644 --- a/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt +++ b/app/src/main/java/ch/rhosys/email/data/auth/AuthressLoginClient.kt @@ -353,13 +353,12 @@ class AuthressLoginClient( * Waits until a bearer token is available, then returns it. Suspends until * [authenticate] plus [completeAuthenticationRequest], or [userIsLoggedIn], * establishes a session. This is the SDK's documented way to obtain the value - * for an Authorization header — but only for a foreground, UI-driven caller - * that is deliberately gating on sign-in (e.g. the login screen itself). It is - * NOT for [ch.rhosys.email.data.remote.api.AuthInterceptor], which attaches - * whatever token is cached right now and never blocks: that interceptor runs - * on OkHttp's own dispatcher for every request, and blocking one of its - * threads on a browser-driven login the request has nothing to do with is - * exactly the kind of stall this class exists to avoid. + * for an Authorization header, and its one legitimate caller is + * [ch.rhosys.email.data.remote.api.AuthInterceptor] — the HTTP call wrapper + * grabbing a token right before an Email API request goes out. It must never + * be called from Authress's own client: a call like `POST /authentication` is + * what establishes the session, so waiting on its own result here would just + * deadlock until the timeout. * * Returns null if no token arrives within [timeoutInMillis]; 0 means do not * wait at all, matching the SDK. diff --git a/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt b/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt index 87bdb82..a614a34 100644 --- a/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt +++ b/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt @@ -1,28 +1,29 @@ package ch.rhosys.email.data.remote.api +import kotlinx.coroutines.runBlocking import okhttp3.Interceptor import okhttp3.Response /** - * Attaches the Authress session token to API calls. + * Attaches the Authress session token to Email API calls — the one place that + * should ever call [ch.rhosys.email.data.auth.AuthressLoginClient.waitForToken]: + * this is the HTTP call wrapper, grabbing the token right before the request + * that needs it. It returns immediately when a token is already cached, and + * otherwise waits briefly for one being established rather than firing a + * request that's certain to be rejected — e.g. a token that expired between + * route changes, while [AppNavHost][ch.rhosys.email.presentation.navigation.AppNavHost]'s + * `userIsLoggedIn()` refresh is still in flight. * - * Deliberately synchronous and non-blocking: [tokenProvider] reads whatever - * token is cached right now (see [ch.rhosys.email.data.auth.AuthressLoginClient.getToken]) - * and nothing more. This interceptor runs on OkHttp's dispatcher for every - * request — it is not the right place to await a session that only a - * foreground, user-driven flow (the login screen, waiting on the browser) can - * establish. An earlier version called the suspend `waitForToken()` here via - * `runBlocking`, which meant an ordinary API call could sit blocked on a pool - * thread for its full timeout waiting on unrelated browser-driven login — - * exactly the kind of stall this class exists to attach a token quickly, not - * cause. If no token is cached, the request goes out without one and the - * caller sees the resulting 401 like any other API error; ensuring a session - * is ready is [ch.rhosys.email.presentation.navigation.AppNavHost]'s job via - * `userIsLoggedIn()`, not this interceptor's. + * `runBlocking` is safe here — OkHttp interceptors run on OkHttp's own + * dispatcher, never the main thread. It only stays safe because this + * interceptor is never installed on Authress's own client: Authress's calls + * (see `AppContainer.authHttpClient`) don't carry it, since a call like + * `POST /authentication` is what establishes the session in the first place — + * waiting on its own result here would deadlock until the timeout, every time. */ -class AuthInterceptor(private val tokenProvider: () -> String?) : Interceptor { +class AuthInterceptor(private val tokenProvider: suspend () -> String?) : Interceptor { override fun intercept(chain: Interceptor.Chain): Response { - val token = tokenProvider() + val token = runBlocking { tokenProvider() } val request = chain.request().newBuilder().apply { if (token != null) addHeader("Authorization", "Bearer $token") }.build() diff --git a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt index 15ef504..c41736c 100644 --- a/app/src/main/java/ch/rhosys/email/di/AppContainer.kt +++ b/app/src/main/java/ch/rhosys/email/di/AppContainer.kt @@ -83,13 +83,13 @@ class AppContainer(private val context: Context) { } /** - * For the Email API only. Adds bearer auth (from whatever token is cached right - * now — see [AuthInterceptor], deliberately non-blocking) and the same - * timing-log visibility Authress calls get, plus debug body logging. + * For the Email API only. Adds bearer auth via [AuthInterceptor] — the HTTP + * call wrapper that grabs the token right before hitting the backend — plus + * the same timing-log visibility Authress calls get, and debug body logging. */ private val okHttpClient: OkHttpClient by lazy { authHttpClient.newBuilder() - .addInterceptor(AuthInterceptor { authManager.getToken() }) + .addInterceptor(AuthInterceptor { authManager.waitForToken() }) .addInterceptor(ApiLoggingInterceptor(appLogger)) .apply { if (BuildConfig.DEBUG) { diff --git a/todo.md b/todo.md index a942f57..2cc5ec9 100644 --- a/todo.md +++ b/todo.md @@ -26,12 +26,15 @@ POST /api/authentication/{id}/tokens -> session cookies The session lives in the `authorization` and `user` cookies rather than an access/refresh pair. `userIsLoggedIn()` refreshes it via `PATCH /session` and is -called on every route change, per the SDK's own recommendation. `AuthInterceptor` -attaches whatever token is cached synchronously and never blocks a request on it; -`waitForToken()` is only for a foreground caller deliberately gating on sign-in -(the login screen) — an interceptor that `runBlocking`'d it used to stall every -Email API call for up to 5s whenever no session existed yet, which was also why -the very first Authress call of a fresh login was stalling. +called on every route change, per the SDK's own recommendation; `AuthInterceptor` +calls `waitForToken()` to grab the bearer token right before an Email API +request goes out — the only place that should ever call it. That's safe +(`runBlocking` inside an OkHttp interceptor never touches the main thread) as +long as Authress's own client never carries this interceptor: `POST +/authentication` is what establishes the session, so waiting on its own result +there deadlocked until the timeout — which was also why the very first Authress +call of a fresh login used to stall for 5s. Authress now gets its own client +(`authHttpClient`) without `AuthInterceptor` at all. The duplicate redirect claim is gone with AppAuth: MainActivity is now the only component matching the scheme, and it forwards the redirect through