Add deep Mistral request logging and tighten coordinator wait

Author: Android-PowerUser

app/src/main/kotlin/com/google/ai/sample/feature/multimodal/PhotoReasoningViewModel.kt

@@ -1034,6 +1034,10 @@ class PhotoReasoningViewModel(
         screenInfoForPrompt: String? = null,
         imageUrisForChat: List<String>? = null
     ) {
+        Log.d(
+            TAG,
+            "reasonWithMistral: start, images=${selectedImages.size}, screenInfo=${!screenInfoForPrompt.isNullOrBlank()}, chatSize=${_chatState.getAllMessages().size}"
+        )
         _uiState.value = PhotoReasoningUiState.Loading
         _showStopNotificationFlow.value = true
         val context = appContext
@@ -1062,6 +1066,7 @@ class PhotoReasoningViewModel(
     currentReasoningJob?.cancel()
     currentReasoningJob = viewModelScope.launch(Dispatchers.IO) {
         try {
+            Log.d(TAG, "reasonWithMistral: launched IO job")
             val currentModel = com.google.ai.sample.GenerativeAiViewModelFactory.getCurrentModel()
             val genSettings = com.google.ai.sample.util.GenerationSettingsPreferences.loadSettings(context, currentModel.modelName)
 
@@ -1132,6 +1137,7 @@ class PhotoReasoningViewModel(
             val availableKeys = apiKeyManager.getApiKeys(ApiProvider.MISTRAL)
                 .filter { it.isNotBlank() }
                 .distinct()
+            Log.d(TAG, "reasonWithMistral: availableKeys=${availableKeys.size}")
             if (availableKeys.isEmpty()) {
                 throw IOException("Mistral API key not found.")
             }
@@ -1149,6 +1155,7 @@ class PhotoReasoningViewModel(
                 client.newCall(buildRequest(selectedKey)).execute()
             }
             val finalResponse = coordinated.response
+            Log.d(TAG, "reasonWithMistral: coordinated response code=${finalResponse.code}")
 
             if (!finalResponse.isSuccessful) {
                 val errBody = finalResponse.body?.string()
@@ -1163,6 +1170,7 @@ class PhotoReasoningViewModel(
                     processCommandsIncrementally(accText)
                 }
             }
+            Log.d(TAG, "reasonWithMistral: stream parse finished, responseLength=${aiResponseText.length}")
             finalResponse.close()
 
             withContext(Dispatchers.Main) {
@@ -1181,6 +1189,7 @@ class PhotoReasoningViewModel(
             }
         } finally {
             withContext(Dispatchers.Main) {
+                Log.d(TAG, "reasonWithMistral: finally, draining queued auto-screenshot requests")
                 releaseAndDrainMistralAutoScreenshotQueue()
                 refreshStopButtonState()
             }
@@ -2332,9 +2341,10 @@ private fun processCommands(text: String) {
         synchronized(mistralAutoScreenshotQueueLock) {
             if (mistralAutoScreenshotInFlight) {
                 queuedMistralScreenshotRequest = request
-                Log.d(TAG, "Mistral auto screenshot request queued (latest wins).")
+                Log.d(TAG, "Mistral auto screenshot request queued (latest wins). uri=$screenshotUri")
             } else {
                 mistralAutoScreenshotInFlight = true
+                Log.d(TAG, "Mistral auto screenshot request becomes in-flight. uri=$screenshotUri")
                 shouldStartNow = true
             }
         }
@@ -2344,6 +2354,7 @@ private fun processCommands(text: String) {
     }
 
     private fun dispatchMistralAutoScreenshotRequest(request: QueuedMistralScreenshotRequest) {
+        Log.d(TAG, "Dispatching Mistral auto screenshot request. uri=${request.screenshotUri}")
         reason(
             userInput = createGenericScreenshotPrompt(),
             selectedImages = listOf(request.bitmap),
@@ -2357,9 +2368,11 @@ private fun processCommands(text: String) {
             val queued = queuedMistralScreenshotRequest
             if (queued == null) {
                 mistralAutoScreenshotInFlight = false
+                Log.d(TAG, "Mistral auto screenshot queue drained completely. inFlight=false")
                 null
             } else {
                 queuedMistralScreenshotRequest = null
+                Log.d(TAG, "Mistral auto screenshot queue has pending request to drain.")
                 queued
             }
         }

app/src/main/kotlin/com/google/ai/sample/network/MistralRequestCoordinator.kt

@@ -1,9 +1,11 @@
 package com.google.ai.sample.network
 
+import android.util.Log
 import kotlinx.coroutines.delay
 import kotlinx.coroutines.sync.Mutex
 import kotlinx.coroutines.sync.withLock
 import okhttp3.Response
+import java.util.concurrent.atomic.AtomicLong
 import kotlin.math.max
 import kotlin.math.roundToLong
 
@@ -13,10 +15,17 @@ internal data class MistralCoordinatedResponse(
 )
 
 internal object MistralRequestCoordinator {
+    private const val TAG = "MistralCoordinator"
     private const val MIN_INTERVAL_MS = 1500L
-    private const val MAX_SERVER_DELAY_MS = 60_000L
+    private const val MAX_SERVER_DELAY_MS = 5_000L
     private val cooldownMutex = Mutex()
     private val nextAllowedRequestAtMsByKey = mutableMapOf<String, Long>()
+    private val requestId = AtomicLong(0L)
+
+    private fun keyFingerprint(key: String): String {
+        if (key.length <= 8) return key
+        return "${key.take(4)}…${key.takeLast(4)}"
+    }
 
     private suspend fun markKeyCooldown(
         key: String,
@@ -71,6 +80,8 @@ internal object MistralRequestCoordinator {
         request: suspend (apiKey: String) -> Response
     ): MistralCoordinatedResponse {
         require(apiKeys.isNotEmpty()) { "No Mistral API keys provided." }
+        val rid = requestId.incrementAndGet()
+        Log.d(TAG, "[$rid] execute start: keys=${apiKeys.size}, maxAttempts=$maxAttempts")
 
         var consecutiveFailures = 0
         var blockedKeysThisRound = mutableSetOf<String>()
@@ -91,6 +102,10 @@ internal object MistralRequestCoordinator {
                     selectedKey = candidate
                 }
             }
+            Log.d(
+                TAG,
+                "[$rid] attempt=${consecutiveFailures + 1}, selectedKey=${keyFingerprint(selectedKey)}, waitMs=$waitMs, blocked=${blockedKeysThisRound.size}"
+            )
             if (waitMs > 0L) {
                 delay(waitMs)
             }
@@ -101,26 +116,41 @@ internal object MistralRequestCoordinator {
                 val retryAfterMs = parseRetryAfterMs(response.header("Retry-After"))
                 val resetDelayMs = parseRateLimitResetDelayMs(response, requestEndMs)
                 val serverRequestedDelayMs = max(retryAfterMs ?: 0L, resetDelayMs ?: 0L)
+                Log.d(
+                    TAG,
+                    "[$rid] response code=${response.code}, retryAfterMs=${retryAfterMs ?: -1}, resetDelayMs=${resetDelayMs ?: -1}, appliedDelayMs=$serverRequestedDelayMs"
+                )
                 markKeyCooldown(selectedKey, requestEndMs, serverRequestedDelayMs)
 
                 if (response.isSuccessful || !isRetryableFailure(response.code)) {
+                    Log.d(TAG, "[$rid] returning response code=${response.code} with key=${keyFingerprint(selectedKey)}")
                     return MistralCoordinatedResponse(response = response, apiKey = selectedKey)
                 }
 
                 response.close()
                 blockedKeysThisRound.add(selectedKey)
                 consecutiveFailures++
                 val adaptiveDelay = adaptiveRetryDelayMs(consecutiveFailures)
+                Log.w(
+                    TAG,
+                    "[$rid] retryable failure code=${response.code}, consecutiveFailures=$consecutiveFailures, adaptiveDelay=$adaptiveDelay"
+                )
                 markKeyCooldown(selectedKey, requestEndMs, max(serverRequestedDelayMs, adaptiveDelay))
             } catch (e: Exception) {
                 val requestEndMs = System.currentTimeMillis()
                 blockedKeysThisRound.add(selectedKey)
                 consecutiveFailures++
+                Log.e(
+                    TAG,
+                    "[$rid] exception on key=${keyFingerprint(selectedKey)}, consecutiveFailures=$consecutiveFailures: ${e.message}",
+                    e
+                )
                 markKeyCooldown(selectedKey, requestEndMs, adaptiveRetryDelayMs(consecutiveFailures))
                 if (consecutiveFailures >= maxAttempts) throw e
             }
         }
 
+        Log.e(TAG, "[$rid] exhausted attempts ($maxAttempts) without success")
         throw IllegalStateException("Mistral request failed after $maxAttempts attempts.")
     }
 }