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 b97cd3e..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 @@ -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() @@ -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 = 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,18 +228,33 @@ class AuthressLoginClient( * already redeemed. */ suspend fun completeAuthenticationRequest(uri: Uri): Result = 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, @@ -211,6 +262,7 @@ class AuthressLoginClient( "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()) } } 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..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 @@ -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 { + 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 } 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/AuthInterceptor.kt b/app/src/main/java/ch/rhosys/email/data/remote/api/AuthInterceptor.kt index 9e77785..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 @@ -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 { 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..c41736c 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,36 @@ class AppContainer(private val context: Context) { .build() } - private val okHttpClient: OkHttpClient by lazy { + /** + * 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 + // 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 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.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 +121,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 2338ba7..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 } @@ -81,8 +85,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() } @@ -114,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() } }) { @@ -132,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 new file mode 100644 index 0000000..a760f02 --- /dev/null +++ b/app/src/main/java/ch/rhosys/email/presentation/components/DebugLogOverlay.kt @@ -0,0 +1,147 @@ +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.runtime.setValue +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) 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() } diff --git a/todo.md b/todo.md index a78bfd7..2cc5ec9 100644 --- a/todo.md +++ b/todo.md @@ -26,8 +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; `waitForToken()` -supplies the Authorization header. +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