Instrument Authress login flow with timing logs and a diagnostic overlay

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) }
     }
 

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> = _authStatus.asStateFlow()
@@ -127,13 +139,33 @@ class AuthressLoginClient(
      * once the browser has been launched; completion arrives via the deep link.
      */
     suspend fun authenticate(options: AuthenticationOptions = AuthenticationOptions()): Result<Unit> = 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()
         // 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 +175,7 @@ class AuthressLoginClient(
                 "audiences" to options.audiences,
             ),
         )
+        logAntiAbuseHash(antiAbuseHash, System.currentTimeMillis() - hashStartedAt)
         val body = JSONObject()
             .put("redirectUrl", redirectUri)
             .put("applicationId", BuildConfig.AUTHRESS_APPLICATION_ID)
@@ -164,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(
@@ -173,9 +207,11 @@ class AuthressLoginClient(
             ),
         )
 
+        _authStatus.value = AuthStatus.OpeningBrowser
         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,25 +228,41 @@ class AuthressLoginClient(
      * already redeemed.
      */
     suspend fun completeAuthenticationRequest(uri: Uri): Result<Unit> = runCatching {
-        _authStatus.value = AuthStatus.CompletingSignIn
+        val flowStartedAt = System.currentTimeMillis()
         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(
                 "applicationId" to BuildConfig.AUTHRESS_APPLICATION_ID,
                 "authenticationRequestId" to authenticationRequestId,
                 "code" to code,
             ),
         )
+        logAntiAbuseHash(antiAbuseHash, System.currentTimeMillis() - hashStartedAt)
         val body = JSONObject()
             .put("code", code)
             .put("codeVerifier", pending.codeVerifier)
@@ -223,6 +275,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 +288,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 +340,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
@@ -295,11 +350,15 @@ 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, 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.
@@ -425,28 +484,44 @@ 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")
             .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())
         }
     }

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,16 @@ 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, Any?>): String {
+    suspend fun calculateAntiAbuseHash(props: Map<String, Any?>): String =
+        withContext(Dispatchers.Default) { searchAntiAbuseHash(props) }
+
+    private fun searchAntiAbuseHash(props: Map<String, Any?>): String {
         val timestamp = System.currentTimeMillis()
         val valueString = props.values
             .filterNot { it == null || it == "" || it == false }

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
+    }
+}

app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt

@@ -5,15 +5,21 @@ 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.
  *
- * 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.
+ * `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: suspend () -> String?) : Interceptor {
     override fun intercept(chain: Interceptor.Chain): Response {

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/<version>`.
+ * 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/<version>`.
  */
 class UserAgentInterceptor : Interceptor {
     override fun intercept(chain: Interceptor.Chain): Response {