From f30b93ef049a69f638f9335894462070d8946384 Mon Sep 17 00:00:00 2001 From: John Trujillo Date: Wed, 26 Aug 2026 16:45:13 -0500 Subject: [PATCH 1/2] feat(ai): give the agent the real build log and a run_app that waits read_build_output anchors on the first error and run_app waits for the build callback, surviving chat-view teardown; self-answered tool calls are ignored. --- .../plugins/aicore/fragments/ChatFragment.kt | 106 +++++++--- .../plugins/aicore/logging/AgentTrace.kt | 6 +- .../plugins/aicore/logging/LogTags.kt | 4 +- .../plugins/aicore/models/AgentState.kt | 15 ++ .../plugins/aicore/plugin/AiCorePlugin.kt | 5 + .../plugins/aicore/tool/ToolCallExtractor.kt | 42 +++- .../tool/handlers/ReadBuildOutputHandler.kt | 94 ++++++++- .../aicore/tool/handlers/RunAppHandler.kt | 157 +++++++++----- .../plugins/aicore/viewmodel/ChatViewModel.kt | 97 +++++++-- .../aicore/viewmodel/ChatViewModelStore.kt | 74 +++++++ .../aicore/tool/ToolCallExtractorTest.kt | 60 ++++++ .../handlers/ReadBuildOutputHandlerTest.kt | 194 ++++++++++++++++++ .../aicore/tool/handlers/RunAppHandlerTest.kt | 166 +++++++++++++++ .../viewmodel/ChatViewModelStoreTest.kt | 49 +++++ 14 files changed, 960 insertions(+), 109 deletions(-) create mode 100644 ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStore.kt create mode 100644 ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt create mode 100644 ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt create mode 100644 ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStoreTest.kt diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt index 6153ddad..8c88698c 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt @@ -12,7 +12,6 @@ import androidx.core.view.doOnAttach import androidx.core.view.isVisible import androidx.fragment.app.Fragment import androidx.lifecycle.Lifecycle -import androidx.lifecycle.ViewModelProvider import androidx.lifecycle.lifecycleScope import androidx.lifecycle.repeatOnLifecycle import androidx.recyclerview.widget.LinearLayoutManager @@ -24,11 +23,14 @@ import com.itsaky.androidide.plugins.aicore.BuildConfig import com.itsaky.androidide.plugins.aicore.R import com.itsaky.androidide.plugins.aicore.adapters.ChatAdapter import com.itsaky.androidide.plugins.aicore.databinding.FragmentChatBinding +import com.itsaky.androidide.plugins.aicore.logging.AgentTrace import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import com.itsaky.androidide.plugins.aicore.models.AgentState import com.itsaky.androidide.plugins.aicore.models.isRunning +import com.itsaky.androidide.plugins.aicore.models.traceLabel import com.itsaky.androidide.plugins.aicore.plugin.AiCorePlugin import com.itsaky.androidide.plugins.aicore.viewmodel.ChatViewModel +import com.itsaky.androidide.plugins.aicore.viewmodel.ChatViewModelStore import com.itsaky.androidide.plugins.base.PluginFragmentHelper import com.itsaky.androidide.plugins.services.IdeProjectService import com.itsaky.androidide.plugins.services.IdeTooltipService @@ -63,6 +65,9 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { /** The message list's layout-declared padding, before any cutout inset is added. */ private val basePadding = Rect() + /** Message count last logged, so streaming re-emissions do not each get a line. */ + private var renderedMessageCount = -1 + private val tooltipService: IdeTooltipService? by lazy { try { PluginFragmentHelper.getServiceRegistry(AiCorePlugin.PLUGIN_ID) @@ -106,17 +111,43 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { return binding.root } + /** + * Tears down the view only. It deliberately does **not** stop the agent: the host removes this + * fragment whenever the user switches bottom-sheet tabs, and cancelling here killed the run in + * flight — a `run_app` wait can be ten minutes long — so the build finished with nobody left to + * report it. Only Stop, Clear Chat and plugin dispose cancel a run. + */ override fun onDestroyView() { if (::chatAdapter.isInitialized) { chatAdapter.stopAllAnimations() } super.onDestroyView() - viewModel.stopProcessing() + // runInFlight=true here, followed by that run still reporting, is the tab-switch fix + // working; the run being gone from the trace after it is the bug coming back. Guarded + // because a log line must never be the thing that takes the IDE down. + if (::viewModel.isInitialized) { + val state = viewModel.agentState.value + AgentTrace.stage( + "UI", + "chat view destroyed runInFlight=${state.isRunning} state=${state.traceLabel}" + ) + } composer?.detach() composer = null _binding = null } + /** + * Writes the transcript out on the way off screen. The ViewModel now outlives this fragment, so + * its onCleared() no longer fires on a tab switch and is no longer the only writer. + */ + override fun onStop() { + super.onStop() + if (::viewModel.isInitialized) { + viewModel.persistState() + } + } + override fun onSaveInstanceState(outState: Bundle) { super.onSaveInstanceState(outState) // The process can be killed while backgrounded even though rotation never recreates us. @@ -129,17 +160,28 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { initializeMarkwon() initializeViewModel() if (!viewModel.isStorageInitialized()) { - viewModel.initializeStorage(requireContext()) + // Application context: the ViewModel outlives this fragment, and the activity. + viewModel.initializeStorage(requireContext().applicationContext) } setupToolbar() setupRecyclerView() setupInputArea() + restoreContextChips() setupCutoutPadding() setupComposer(savedInstanceState) setupStatusBar() setupBackendIndicator() observeViewModel() + AgentTrace.stage( + "UI", + "chat view created runInFlight=${viewModel.agentState.value.isRunning} " + + "state=${viewModel.agentState.value.traceLabel} " + + "messages=${viewModel.messages.value.size} " + + "contextFiles=${contextFiles.size} " + + "pendingApproval=${viewModel.pendingApprovalRequest.value?.toolName}" + ) + // Check for test prompt from broadcast receiver (E2E testing) injectPendingTestPrompt() } @@ -199,12 +241,13 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { viewModel.refreshBackendLabel() } + /** + * Resolves the plugin-scoped ViewModel rather than a fragment-scoped one, so an agent run + * survives this fragment being removed and re-attaches to the tab that comes back. See + * [ChatViewModelStore]. + */ private fun initializeViewModel() { - // A context getter, not the service, so the ViewModel resolves it lazily. - viewModel = ViewModelProvider( - this, - ChatViewModelFactory { getPluginContext() } - )[ChatViewModel::class.java] + viewModel = ChatViewModelStore.get() } private fun getPluginContext(): PluginContext? { @@ -252,7 +295,7 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { private fun setupInputArea() { binding.sendButton.setOnClickListener { if (viewModel.agentState.value.isRunning) { - viewModel.stopProcessing() + viewModel.stopProcessing(reason = "stop button") } else { val message = binding.promptInputEdittext.text?.toString() ?: return@setOnClickListener if (message.isNotBlank()) { @@ -363,20 +406,22 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { } private suspend fun observeMessages() { - android.util.Log.d(TAG, "observeMessages: Starting to collect messages") viewModel.messages.collect { messages -> val binding = _binding ?: return@collect - android.util.Log.d(TAG, "observeMessages: Received ${messages.size} messages") - messages.forEachIndexed { index, msg -> - android.util.Log.d(TAG, " Message $index: sender=${msg.sender}, text=${msg.text.take(50)}") + // One line, and only when the count moves: this collector re-emits on every streamed + // token, and a per-message dump here made the log unreadable during a run. + if (messages.size != renderedMessageCount) { + renderedMessageCount = messages.size + android.util.Log.d( + TAG, + "rendering $renderedMessageCount messages, last=${messages.lastOrNull()?.sender}" + ) } binding.emptyChatView.isVisible = messages.isEmpty() - android.util.Log.d(TAG, "observeMessages: Calling submitList with ${messages.size} messages") // Sampled before the list changes: streaming re-emits on every token, so scrolling // unconditionally would drag the user back down whenever they scrolled up to read. val stickToBottom = binding.chatRecyclerView.isAtBottom() chatAdapter.submitList(messages) { - android.util.Log.d(TAG, "observeMessages: submitList callback - scrolling to ${messages.size - 1}") if (stickToBottom && messages.isNotEmpty()) { // Null after onDestroyView: submitList posts this callback. _binding?.chatRecyclerView?.scrollToPosition(messages.lastIndex) @@ -408,6 +453,9 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { binding.agentStatusContainer.isVisible = false viewModel.stopStateTimer() showErrorSnackbar(state.message) + // One-shot: an error raised while this tab was gone must not re-raise on every + // later re-attach, now that the state outlives the fragment. + viewModel.clearErrorState() } else -> Unit } @@ -438,6 +486,7 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { private fun showApprovalDialog(request: com.itsaky.androidide.plugins.aicore.tool.ApprovalRequest) { // childFragmentManager makes this fragment the parent, which is how Host is resolved. if (currentApprovalDialog() != null) return + AgentTrace.detail("UI", "approval dialog shown tool=${request.toolName}") ApprovalDialogFragment.newInstance(request).show(childFragmentManager, APPROVAL_DIALOG_TAG) } @@ -445,6 +494,7 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { result: com.itsaky.androidide.plugins.aicore.tool.ApprovalResult, correction: String?, ) { + AgentTrace.detail("UI", "approval decided choice=$result corrected=${correction != null}") viewModel.submitApproval(result, correction) } @@ -468,6 +518,17 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { dialog.show(parentFragmentManager, "file_picker") } + /** + * Rebuilds the attached-file chips from the ViewModel. It keeps the attachments across a tab + * switch, so without this they would still go into the next prompt with nothing on screen + * naming them. + */ + private fun restoreContextChips() { + contextFiles.clear() + contextFiles.addAll(viewModel.contextFiles) + contextFiles.forEach(::addChipForFile) + } + private fun addContextFiles(files: List) { files.forEach { file -> if (!contextFiles.contains(file)) { @@ -559,18 +620,3 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { } } - -/** - * Factory for creating ChatViewModel with PluginContext dependency. - */ -class ChatViewModelFactory( - private val getContext: () -> PluginContext? -) : ViewModelProvider.Factory { - @Suppress("UNCHECKED_CAST") - override fun create(modelClass: Class): T { - if (modelClass.isAssignableFrom(ChatViewModel::class.java)) { - return ChatViewModel(getContext) as T - } - throw IllegalArgumentException("Unknown ViewModel class") - } -} diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/AgentTrace.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/AgentTrace.kt index 3ab5e509..f645aa03 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/AgentTrace.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/AgentTrace.kt @@ -59,11 +59,15 @@ object AgentTrace { fun endRun(outcome: String, turns: Int? = null) { stage("DONE", "outcome=$outcome" + (turns?.let { " turns=$it" } ?: "")) runId = "-" + // Reset too, or the UI lines that follow a run report an elapsed time measured from a run + // that is already over. + runStartMs = 0L } /** * Logs a milestone in the run at INFO — the lines you want when following the flow. - * @param stage short uppercase phase name (PROMPT, LLM, TOOL, APPROVAL, EXEC, …). + * @param stage short uppercase phase name (PROMPT, LLM, PARSE, APPROVAL, EXEC, RESULT, BUILD, + * STATE, UI, CANCEL, DONE). * @param detail structured `key=value` facts. * @param preview optional free text, already previewed by the caller. */ diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/LogTags.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/LogTags.kt index 0e9e224a..3182e2c8 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/LogTags.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/logging/LogTags.kt @@ -3,6 +3,8 @@ package com.itsaky.androidide.plugins.aicore.logging /** * Prefix on every logcat tag this plugin writes, so a line names the plugin that emitted it — every * AI feature shares the host IDE's process, where a bare `ToolRouter` tag names no `.cgp`. Tags read - * `"$LOG_PREFIX.ClassName"`, so `adb logcat -s AiCore.*` is this plugin's whole log. + * `"$LOG_PREFIX.ClassName"`. `logcat -s` matches a tag exactly, so the whole plugin log is + * `adb logcat | grep AiCore.`; one class is `adb logcat -s AiCore.ChatFragment:V`, and the whole + * agent run on one stream is `adb logcat -s AiCore.AgentTrace:V`. */ internal const val LOG_PREFIX = "AiCore" diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt index 593a95fd..ab14509b 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt @@ -77,6 +77,21 @@ sealed class AgentState { data class Error(val message: String) : AgentState() } +/** + * Short name for the trace log: the state and what it is doing, without a data class's field dump + * and without the error text, which is already in the transcript. + */ +val AgentState.traceLabel: String + get() = when (this) { + is AgentState.Idle -> "Idle" + is AgentState.Initializing -> "Initializing" + is AgentState.Thinking -> "Thinking" + is AgentState.Executing -> "Executing(step ${currentStepIndex + 1}/$totalSteps $description)" + is AgentState.Processing -> "Processing" + is AgentState.Cancelling -> "Cancelling" + is AgentState.Error -> "Error" + } + /** * True while a run is in flight, which is what the composer keys its Stop control off. One * definition so the UI cannot drift from it a state at a time. diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/plugin/AiCorePlugin.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/plugin/AiCorePlugin.kt index 0db4372c..3df8dc87 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/plugin/AiCorePlugin.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/plugin/AiCorePlugin.kt @@ -10,6 +10,7 @@ import com.itsaky.androidide.plugins.aicore.services.LlmInferenceServiceImpl import com.itsaky.androidide.plugins.aicore.services.ToolSourceRegistryImpl import com.itsaky.androidide.plugins.aicore.tool.handlers.PathGuard import com.itsaky.androidide.plugins.aicore.tool.sources.ToolSourceStore +import com.itsaky.androidide.plugins.aicore.viewmodel.ChatViewModelStore import com.itsaky.androidide.plugins.extensions.DocumentationExtension import com.itsaky.androidide.plugins.extensions.MenuItem import com.itsaky.androidide.plugins.extensions.PluginSettingsEntry @@ -162,6 +163,10 @@ class AiCorePlugin : IPlugin, UIExtension, DocumentationExtension, SettingsExten // dispose(); this only stops whatever this plugin still has in flight. llmService?.cancelGeneration() + // The chat ViewModel is plugin-scoped, not fragment-scoped, so this is what ends a run + // that outlived its fragment; clearing it persists the transcript first. + ChatViewModelStore.clear() + PathGuard.setProjectRootProvider(null) pluginContext = null llmService = null diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt index 260e708f..9b67e3bf 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt @@ -16,6 +16,35 @@ class ToolCallExtractor { private val TOOL_CALL_REGEX = Regex("""\s*(.+?)\s*""", RegexOption.DOT_MATCHES_ALL) + /** + * A tool result written by the model itself, as a ```tool_response fence or a + * `` tag. Both system prompts forbid these and promise such output is + * ignored; [beforeFabricatedResult] is where that promise is kept. + */ + private val FABRICATED_RESULT_REGEX = + Regex("""```+\s*tool_response|""", RegexOption.IGNORE_CASE) + + /** + * [text] up to the first tool result the model wrote for itself. + * + * A model that answers its own tool call has stopped reporting and started role-playing + * the rest of the conversation, so every call after that point belongs to an invented + * transcript: one reply once yielded 13 calls against a project that did not exist. The + * calls before it were still real, so the reply is truncated rather than discarded. + * + * @param text the model's raw reply. + * @return the leading real portion, or [text] unchanged when nothing was fabricated. + */ + internal fun beforeFabricatedResult(text: String): String { + val match = FABRICATED_RESULT_REGEX.find(text) ?: return text + Log.w( + TAG, + "Reply writes its own tool result at offset ${match.range.first}; " + + "ignoring the ${text.length - match.range.first} chars after it", + ) + return text.substring(0, match.range.first) + } + /** * The prose left once the tool-call envelopes are removed. Worth showing when a `respond` * call carries no message, which usually means the model wrote the answer as prose and @@ -25,7 +54,7 @@ class ToolCallExtractor { * (untagged) tool call rather than something meant for the user to read. */ fun proseOutsideToolCalls(text: String): String? { - val remainder = TOOL_CALL_REGEX.replace(text, "\n").trim() + val remainder = TOOL_CALL_REGEX.replace(beforeFabricatedResult(text), "\n").trim() if (remainder.isEmpty()) return null // A leftover `"tool"` key is an unenveloped call; raw JSON is worse than nothing. if (remainder.contains("\"tool\"")) return null @@ -43,18 +72,21 @@ class ToolCallExtractor { Log.d(TAG, "Extracting tool calls from response (${text.length} chars)") Log.d(TAG, "Response preview: ${text.take(300)}") + // Anything past a tool result the model wrote itself is an invented continuation. + val body = beforeFabricatedResult(text) + // Strategy 1: Explicit XML tags - toolCalls.addAll(extractFromXmlTags(text)) + toolCalls.addAll(extractFromXmlTags(body)) // Strategy 2: Bare JSON objects if no XML found if (toolCalls.isEmpty()) { - toolCalls.addAll(extractFromJsonObjects(text)) + toolCalls.addAll(extractFromJsonObjects(body)) } - Log.d(TAG, "Extracted ${toolCalls.size} tool calls from response (${text.length} chars)") + Log.d(TAG, "Extracted ${toolCalls.size} tool calls from response (${body.length} chars)") // Warn if we found incomplete tool calls - if (text.contains("") && text.count { it == '<' } > text.count { it == '>' }) { + if (body.contains("") && body.count { it == '<' } > body.count { it == '>' }) { Log.w(TAG, "WARNING: Found incomplete tool call tags in response. Response may have been truncated.") Log.w(TAG, "Full response: $text") } diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt index 8ad26ea7..0feb318d 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt @@ -2,13 +2,21 @@ package com.itsaky.androidide.plugins.aicore.tool.handlers import android.util.Log import com.itsaky.androidide.plugins.PluginContext +import com.itsaky.androidide.plugins.aicore.logging.AgentTrace import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import com.itsaky.androidide.plugins.aicore.models.ToolResult import com.itsaky.androidide.plugins.aicore.tool.ToolHandler import com.itsaky.androidide.plugins.services.IdeBuildService +import kotlinx.coroutines.CancellationException private const val TAG = "$LOG_PREFIX.ReadBuildOutputHandler" +/** The slice of a build log handed to the model, and whether it starts at the first error. */ +internal data class OutputWindow( + val text: String, + val anchoredOnError: Boolean, +) + /** * Handler for reading the current build output. */ @@ -35,24 +43,31 @@ class ReadBuildOutputHandler( val output = buildService.getBuildOutput() if (output.isNullOrBlank()) { Log.d(TAG, "No build output available") + AgentTrace.detail("BUILD", "read_build_output chars=0 (host returned nothing)") ToolResult.success( message = "No build output available", data = "(No recent build output)" ) } else { - // Truncate to last 2000 chars to avoid overwhelming the LLM - val truncated = if (output.length > 2000) { - "...[truncated]...\n" + output.takeLast(2000) - } else { - output - } - - Log.d(TAG, "Read ${truncated.length} chars of build output") + val window = windowFor(output) + Log.d(TAG, "Read ${window.text.length} chars, anchored=${window.anchoredOnError}") + AgentTrace.detail( + "BUILD", + "read_build_output chars=${window.text.length} " + + "anchoredOnError=${window.anchoredOnError} hostChars=${output.length}" + ) ToolResult.success( - message = "Build output (last ${truncated.length} characters)", - data = truncated + message = if (window.anchoredOnError) { + "Build output from the first error (${window.text.length} characters)" + } else { + "Build output (last ${window.text.length} characters)" + }, + data = window.text ) } + } catch (ce: CancellationException) { + // An Exception on the JVM, so the catch below would report Stop as a read failure. + throw ce } catch (e: Exception) { Log.e(TAG, "Error reading build output", e) ToolResult.failure( @@ -61,4 +76,63 @@ class ReadBuildOutputHandler( ) } } + + companion object { + /** Maximum characters of build log handed to the model. */ + internal const val MAX_OUTPUT_CHARS = 8000 + + private const val TRUNCATION_MARKER = "...[truncated]...\n" + + // The host strips line timing prefixes; tolerated here so the window is right either way. + private val LINE_PREFIX = Regex("""^(?:\[\d{2}:\d{2}:\d{2}\.\d{3}] )?(?:Δ\d+ms\s+)?""") + + /** + * Markers that begin the part of a build log worth reading. Warnings are deliberately + * absent: a build with 200 warnings and one error must anchor on the error. + */ + private val ERROR_MARKERS = listOf( + Regex("""^e: """), + Regex("""(?:^|\s)error:"""), + Regex("""^FAILURE: Build failed"""), + Regex("""^\* What went wrong:"""), + Regex("""^Execution failed for task"""), + Regex("""^BUILD FAILED"""), + Regex("""^Caused by:"""), + ) + + /** + * Selects the slice of [output] the model needs. A plain tail is the wrong window for a + * failed build — the tail is the summary and boilerplate, while the compiler errors sit + * hundreds of lines earlier — so the window starts at the first error line when there is one. + */ + internal fun windowFor(output: String): OutputWindow { + val errorOffset = firstErrorOffset(output) + val body = if (errorOffset == null) output else output.substring(errorOffset) + val overflows = body.length > MAX_OUTPUT_CHARS + // A cascade of hundreds of errors still ends at the summary, so overflow re-tails. + val text = if (overflows) body.takeLast(MAX_OUTPUT_CHARS) else body + val dropped = overflows || (errorOffset ?: 0) > 0 + return OutputWindow( + text = if (dropped) TRUNCATION_MARKER + text else text, + anchoredOnError = errorOffset != null && !overflows, + ) + } + + /** Character offset of the first line that looks like a compiler or Gradle failure. */ + private fun firstErrorOffset(output: String): Int? { + var lineStart = 0 + while (true) { + val newline = output.indexOf('\n', lineStart) + val lineEnd = if (newline == -1) output.length else newline + if (isErrorLine(output.substring(lineStart, lineEnd))) return lineStart + if (newline == -1) return null + lineStart = newline + 1 + } + } + + private fun isErrorLine(line: String): Boolean { + val body = LINE_PREFIX.replaceFirst(line, "") + return ERROR_MARKERS.any { it.containsMatchIn(body) } + } + } } diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt index 5d233ddd..8a9ae41f 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt @@ -2,15 +2,32 @@ package com.itsaky.androidide.plugins.aicore.tool.handlers import android.util.Log import com.itsaky.androidide.plugins.PluginContext +import com.itsaky.androidide.plugins.aicore.logging.AgentTrace import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import com.itsaky.androidide.plugins.aicore.models.ToolResult import com.itsaky.androidide.plugins.aicore.tool.ToolHandler import com.itsaky.androidide.plugins.services.BuildAndLaunchCallback import com.itsaky.androidide.plugins.services.IdeBuildService +import kotlinx.coroutines.CancellationException +import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.delay +import kotlinx.coroutines.launch +import kotlinx.coroutines.suspendCancellableCoroutine +import kotlinx.coroutines.withTimeoutOrNull +import java.util.concurrent.atomic.AtomicBoolean +import kotlin.coroutines.resume private const val TAG = "$LOG_PREFIX.RunAppHandler" +/** How long to wait for the build callback before reporting the build still running. */ +internal const val BUILD_TIMEOUT_MS = 10 * 60 * 1000L + +/** + * How often to log that the wait is still alive. A build can hold the agent for ten minutes, and + * without a heartbeat that stretch of logcat is indistinguishable from a hung agent. + */ +internal const val BUILD_PROGRESS_LOG_INTERVAL_MS = 30 * 1000L + /** * Handler for running/building the app. */ @@ -18,14 +35,18 @@ class RunAppHandler( private val pluginContext: PluginContext ) : ToolHandler { override val toolName = "run_app" - override val description = "Build and run the Android app on the connected device or emulator" + + // The install is gated on a system prompt only the user can answer, so the model is told the + // success it gets back is weaker than "the app is running" — otherwise it reports the launch. + override val description = "Build the app and install it on this device. The user has to " + + "confirm a system install prompt, so success means the install started, not that the " + + "app is on screen" + // Build operation requires approval for safety override val requiresApproval = true override suspend fun execute(args: Map): ToolResult { return try { - Log.d(TAG, "Run app tool called - v3 with retry") - val buildService = pluginContext.services.get(IdeBuildService::class.java) if (buildService == null) { Log.w(TAG, "IdeBuildService not available - service is null") @@ -35,72 +56,112 @@ class RunAppHandler( ) } - Log.d(TAG, "BuildService obtained successfully") - - val buildInProgress = buildService.isBuildInProgress() - Log.d(TAG, "Build in progress: $buildInProgress") - - if (buildInProgress) { + if (buildService.isBuildInProgress()) { + Log.d(TAG, "A build is already in progress") return ToolResult.failure( "Build already running", "A build is already in progress. Please wait for it to complete before running again." ) } - // Retry waiting for tooling server with exponential backoff - val maxRetries = 10 - var toolingStarted = false - var totalWaitTime = 0L - for (attempt in 1..maxRetries) { - toolingStarted = buildService.isToolingServerStarted() - Log.d(TAG, "Tooling server check (attempt $attempt/$maxRetries): $toolingStarted") - - if (toolingStarted) { - Log.d(TAG, "Tooling server is now ready after $totalWaitTime ms") - break - } - - if (attempt < maxRetries) { - val delayMs = 300L * attempt // 300ms, 600ms, 900ms, 1.2s, 1.5s, 1.8s, 2.1s, 2.4s, 2.7s - Log.d(TAG, "Tooling server not ready, waiting ${delayMs}ms before retry...") - delay(delayMs) - totalWaitTime += delayMs + Log.d(TAG, "Triggering app build and launch...") + AgentTrace.stage("BUILD", "run_app triggered; waiting for the build callback") + val startMs = System.currentTimeMillis() + val outcome = withTimeoutOrNull(BUILD_TIMEOUT_MS) { + coroutineScope { + val heartbeat = launch { logProgressUntilCancelled(startMs) } + try { + awaitBuild(buildService) + } finally { + heartbeat.cancel() + } } } + val waitedMs = System.currentTimeMillis() - startMs - if (!toolingStarted) { - Log.w(TAG, "Tooling server did not initialize within ${totalWaitTime + 300}ms, proceeding anyway (may fail)") - // Try to proceed anyway - the service might initialize during the build - Log.d(TAG, "Attempting to run app despite tooling server not being ready...") + if (outcome == null) { + Log.w(TAG, "Build did not report back within $BUILD_TIMEOUT_MS ms") + AgentTrace.refusal( + "BUILD", + "run_app timed out waitedMs=$waitedMs", + "no callback within ${BUILD_TIMEOUT_MS / 1000}s; the build may still be running" + ) + return ToolResult.failure( + "Build still running", + "The build did not finish within 10 minutes and may still be running. " + + "Call read_build_output to see how far it got." + ) } - Log.d(TAG, "Triggering app build and launch...") - return try { - // Trigger the build - fire and forget pattern - buildService.runApp(object : BuildAndLaunchCallback { - override fun onComplete(success: Boolean, message: String) { - Log.i(TAG, "Build callback: success=$success, message=$message") - } - }) - - Log.d(TAG, "Build triggered, returning success") + val (success, message) = outcome + AgentTrace.stage( + "BUILD", + "run_app outcome=${if (success) "success" else "failure"} waitedMs=$waitedMs", + AgentTrace.preview(message) + ) + if (success) { + Log.i(TAG, "Build succeeded: $message") ToolResult.success( - message = "Build triggered successfully", - data = "The app build is now running in the background. Output will appear in the IDE's build panel." + message = "Build succeeded", + data = message ) - } catch (e: Exception) { - Log.e(TAG, "Failed to trigger build: ${e.message}", e) + } else { + Log.w(TAG, "Build failed: $message") ToolResult.failure( - "Failed to trigger build", - "Error: ${e.message ?: "Unknown error"}" + "Build failed", + "$message\n\nCall read_build_output for the compiler errors." ) } + } catch (ce: CancellationException) { + // An Exception on the JVM, so the catch below would report Stop as a build failure. + throw ce } catch (e: Exception) { Log.e(TAG, "Exception in run app tool", e) - return ToolResult.failure( + ToolResult.failure( "Error: ${e.javaClass.simpleName}", "${e.message ?: "Unknown error"}\n\n${e.stackTraceToString()}" ) } } + + /** + * Logs one line every [BUILD_PROGRESS_LOG_INTERVAL_MS] for as long as the wait lasts, so a long + * build reads as a running build rather than as a stalled agent. Cancelled by its caller the + * moment the callback lands. + * + * @param startMs when the wait began, for the elapsed figure. + */ + private suspend fun logProgressUntilCancelled(startMs: Long) { + while (true) { + delay(BUILD_PROGRESS_LOG_INTERVAL_MS) + val seconds = (System.currentTimeMillis() - startMs) / 1000 + AgentTrace.detail("BUILD", "run_app still waiting elapsed=${seconds}s") + } + } + + /** + * Starts the build and suspends until [BuildAndLaunchCallback] reports back. + * @return the callback's success flag paired with its message. + */ + private suspend fun awaitBuild(buildService: IdeBuildService): Pair = + suspendCancellableCoroutine { continuation -> + // The host reports completion from several paths, and synchronously when it has no + // run-app provider at all; a second resume on a resumed continuation throws. + val reported = AtomicBoolean(false) + val callback = object : BuildAndLaunchCallback { + override fun onComplete(success: Boolean, message: String) { + if (reported.compareAndSet(false, true)) { + continuation.resume(success to message) + } + } + } + try { + buildService.runApp(callback) + } catch (e: Exception) { + Log.e(TAG, "Failed to trigger build", e) + if (reported.compareAndSet(false, true)) { + continuation.resumeWith(Result.failure(e)) + } + } + } } diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModel.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModel.kt index eb63fa7e..c79ab84d 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModel.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModel.kt @@ -15,6 +15,8 @@ import com.itsaky.androidide.plugins.aicore.models.ChatMessage import com.itsaky.androidide.plugins.aicore.models.ChatSession import com.itsaky.androidide.plugins.aicore.models.MessageStatus import com.itsaky.androidide.plugins.aicore.models.Sender +import com.itsaky.androidide.plugins.aicore.models.isRunning +import com.itsaky.androidide.plugins.aicore.models.traceLabel import com.itsaky.androidide.plugins.aicore.models.ToolResult import com.itsaky.androidide.plugins.aicore.tool.AgentLoop import com.itsaky.androidide.plugins.aicore.tool.AgentTools @@ -47,6 +49,7 @@ import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CompletableDeferred import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.Job +import kotlinx.coroutines.NonCancellable import kotlinx.coroutines.delay import kotlinx.coroutines.flow.MutableStateFlow import kotlinx.coroutines.flow.SharingStarted @@ -121,6 +124,22 @@ class ChatViewModel( private val _agentState = MutableStateFlow(AgentState.Idle) val agentState: StateFlow = _agentState.asStateFlow() + /** + * Publishes an agent state and traces the transition, so the shape of a run — generating, + * executing which tool, idle, cancelled — reads as one `STATE` line per change in the trace. + * + * Every transition goes through here except the timer's own elapsed-time updates in + * [startStateTimer], which fire ten times a second and would bury everything else. + * + * @param state the state to publish; an unchanged state is neither published nor logged. + */ + private fun setState(state: AgentState) { + val previous = _agentState.value + if (previous == state) return + _agentState.value = state + AgentTrace.stage("STATE", "${previous.traceLabel} -> ${state.traceLabel}") + } + private val _backendStatus = MutableStateFlow(BackendStatus(AiBackend.DEFAULT_ID, false)) val isBackendAvailable: StateFlow = _backendStatus .map { it.isAvailable } @@ -240,7 +259,10 @@ class ChatViewModel( /** The tool awaiting approval, straight from [approvalManager] — no polling in between. */ val pendingApprovalRequest: StateFlow = approvalManager.currentApprovalRequest - private var contextFiles = listOf() + private var _contextFiles = listOf() + + /** Files the user attached; read back by the fragment to rebuild its chips on re-attach. */ + val contextFiles: List get() = _contextFiles private var stateUpdateJob: Job? = null @@ -347,6 +369,24 @@ class ChatViewModel( } } + /** + * Writes the transcript to disk if storage is up. Public because this ViewModel now outlives + * the fragment, so [onCleared] fires only on plugin dispose and can no longer be the only + * writer. + */ + fun persistState() { + if (!isStorageInitialized()) { + AgentTrace.detail("PERSIST", "skipped=storage not initialized") + return + } + persistSessions() + AgentTrace.detail( + "PERSIST", + "sessions=${_sessions.value.size} messages=${_messages.value.size} " + + "session=${_currentSessionId.value}" + ) + } + private fun persistSessions() { storageManager.saveSessions(_sessions.value) storageManager.saveCurrentSessionId(_currentSessionId.value) @@ -363,7 +403,8 @@ class ChatViewModel( * Set context files to include in prompts. */ fun setContextFiles(files: List) { - contextFiles = files + // Copied: the caller passes its own mutable list, which it keeps editing. + _contextFiles = files.toList() } /** @@ -401,7 +442,7 @@ class ChatViewModel( ) _messages.value = _messages.value + errorMessage syncMessageToSession(errorMessage) - _agentState.value = AgentState.Error(text) + setState(AgentState.Error(text)) } /** @@ -626,7 +667,7 @@ class ChatViewModel( totalSteps = toolCalls.size, description = toolCalls.first().name ) - withContext(Dispatchers.Main) { _agentState.value = executingState } + withContext(Dispatchers.Main) { setState(executingState) } startStateTimer(executingState) val results = tools.executor.execute(toolCalls) @@ -799,7 +840,7 @@ class ChatViewModel( withContext(Dispatchers.Main) { _messages.value = _messages.value + userChatMessage syncMessageToSession(userChatMessage) - _agentState.value = AgentState.Processing(str(R.string.msg_generating)) + setState(AgentState.Processing(str(R.string.msg_generating))) } val config = LlmInferenceService.LlmConfig(currentBackendId).apply { @@ -828,7 +869,7 @@ class ChatViewModel( history = history, generate = { turns -> withContext(Dispatchers.Main) { - _agentState.value = AgentState.Processing(str(R.string.msg_generating)) + setState(AgentState.Processing(str(R.string.msg_generating))) } runModelTurn(llmService, turns, config, epoch) }, @@ -883,7 +924,7 @@ class ChatViewModel( stopStateTimer() } - withContext(Dispatchers.Main) { _agentState.value = AgentState.Idle } + withContext(Dispatchers.Main) { setState(AgentState.Idle) } } catch (ce: CancellationException) { AgentTrace.endRun("cancelled") stopStateTimer() @@ -892,11 +933,14 @@ class ChatViewModel( logError("sendMessage failed", e) AgentTrace.endRun("error: ${e.message}") stopStateTimer() - _agentState.value = AgentState.Error(str(R.string.state_error, e.message)) + setState(AgentState.Error(str(R.string.state_error, e.message))) addSystemMessage(str(R.string.state_error, e.message), MessageStatus.ERROR) } finally { // Allow re-entry once the coroutine unwinds. isGenerating.set(false) + // The run can finish with the chat off screen, where nothing else writes. + // NonCancellable so a Stop still saves what the run produced before it. + withContext(NonCancellable + Dispatchers.Main) { persistState() } } } } @@ -1171,6 +1215,10 @@ class ChatViewModel( */ fun clearMessages() { // Clear Chat must also stop any in-flight run, not just wipe the list. + AgentTrace.stage( + "CANCEL", + "reason=clear chat wasRunning=${_agentState.value.isRunning}" + ) generationEpoch.incrementAndGet() approvalManager.cancelPendingApproval() generationJob?.cancel() @@ -1180,7 +1228,7 @@ class ChatViewModel( _messages.value = emptyList() _history.value = emptyList() forgetRetryPoint() - _agentState.value = AgentState.Idle + setState(AgentState.Idle) } /** @@ -1232,12 +1280,31 @@ class ChatViewModel( } } + /** + * Drops a delivered [AgentState.Error] back to [AgentState.Idle]. The state now outlives the + * fragment, so without this every re-attach would raise the same error snackbar again — the + * transcript already keeps the error as a message. + */ + fun clearErrorState() { + if (_agentState.value is AgentState.Error) { + setState(AgentState.Idle) + } + } + /** * Stop any ongoing processing. + * + * @param reason who asked, for the trace: a run that ends without a `CANCEL` line ended on its + * own, and one that ends with it names the gesture that stopped it. */ - fun stopProcessing() { + fun stopProcessing(reason: String = "unspecified") { + AgentTrace.stage( + "CANCEL", + "reason=$reason wasRunning=${_agentState.value.isRunning} " + + "state=${_agentState.value.traceLabel}" + ) generationEpoch.incrementAndGet() - _agentState.value = AgentState.Cancelling + setState(AgentState.Cancelling) // Cancelling the job alone would strand an open approval dialog with nothing awaiting it. approvalManager.cancelPendingApproval() generationJob?.cancel() @@ -1245,7 +1312,7 @@ class ChatViewModel( getLlmService()?.cancelGeneration() stopStateTimer() finalizeInProgressMessages() - _agentState.value = AgentState.Idle + setState(AgentState.Idle) } /** @@ -1284,6 +1351,8 @@ class ChatViewModel( delay(100) val current = _agentState.value if (current !is AgentState.Executing) break + // Straight to the flow, not through setState: ten traced lines a second would + // bury the run's actual steps. _agentState.value = current.copy( elapsedMillis = System.currentTimeMillis() - current.startTime ) @@ -1302,8 +1371,8 @@ class ChatViewModel( override fun onCleared() { super.onCleared() ToolSourceStore.shared.removeChangeListener(toolSourcesChanged) - persistSessions() - stopProcessing() + persistState() + stopProcessing(reason = "viewModel cleared") stopStateTimer() } } diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStore.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStore.kt new file mode 100644 index 00000000..b8a8d23f --- /dev/null +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStore.kt @@ -0,0 +1,74 @@ +package com.itsaky.androidide.plugins.aicore.viewmodel + +import androidx.lifecycle.ViewModel +import androidx.lifecycle.ViewModelProvider +import androidx.lifecycle.ViewModelStore +import com.itsaky.androidide.plugins.PluginContext +import com.itsaky.androidide.plugins.aicore.logging.AgentTrace +import com.itsaky.androidide.plugins.aicore.plugin.AiCorePlugin + +/** + * Owns the Agent chat's [ChatViewModel] for as long as this plugin is loaded. + * + * The host mounts the Agent tab in a FragmentStateAdapter with no offscreen page limit, so + * switching to any other bottom-sheet tab removes ChatFragment outright. A fragment-scoped + * ViewModel is cleared with it, which cancelled the run in flight — for `run_app` that is a wait + * of up to ten minutes — and left the reply with nowhere to land. Keeping the store here means the + * fragment the user comes back to re-attaches to the same run. + */ +object ChatViewModelStore { + + private val store = ViewModelStore() + + /** The instance last handed out, so [get] can log whether a tab switch cost us the run. */ + @Volatile + private var current: ChatViewModel? = null + + /** + * The one [ChatViewModel], created on first call. Main thread only, as every caller is a + * fragment lifecycle callback. + * + * @return the retained ViewModel. + */ + fun get(): ChatViewModel { + val resolved = ViewModelProvider( + store, + // The plugin context is resolved through the companion, never through a fragment: this + // lambda is held for the ViewModel's whole life, and a captured fragment would leak. + ChatViewModelFactory { AiCorePlugin.getContext() } + )[ChatViewModel::class.java] + if (resolved !== current) { + current = resolved + AgentTrace.stage("UI", "chat viewModel created") + } else { + // Reopening the tab mid-run must land here: "created" instead means the run is gone. + AgentTrace.stage("UI", "chat viewModel reused") + } + return resolved + } + + /** Clears the ViewModel, which persists the transcript and stops whatever is still running. */ + fun clear() { + AgentTrace.stage("UI", "chat viewModel cleared") + store.clear() + current = null + } +} + +/** + * Builds the [ChatViewModel] with its plugin-context getter. + * + * @param getContext resolves the plugin context lazily, so a ViewModel created before the plugin + * finished initializing still sees it later. + */ +private class ChatViewModelFactory( + private val getContext: () -> PluginContext? +) : ViewModelProvider.Factory { + @Suppress("UNCHECKED_CAST") + override fun create(modelClass: Class): T { + if (modelClass.isAssignableFrom(ChatViewModel::class.java)) { + return ChatViewModel(getContext) as T + } + throw IllegalArgumentException("Unknown ViewModel class") + } +} diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractorTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractorTest.kt index 65a2603f..7ca12790 100644 --- a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractorTest.kt +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractorTest.kt @@ -102,4 +102,64 @@ class ToolCallExtractorTest { fun givenPlainProse_whenReadingTheProse_thenItComesBackUnchanged() { assertEquals("Hello, how can I help?", ToolCallExtractor.proseOutsideToolCalls("Hello, how can I help?")) } + + /** + * The reply shape that ran 12 tools for a "read the build output" prompt: the model answered + * its own first call and role-played the rest of the session against a project that did not + * exist. Only the call before the invented result is real. + */ + private val hallucinatedTranscript = + """ + {"tool":"read_build_output","args":{}} + ```tool_response + The build has not been executed. + ``` + {"tool":"list_files","args":{"directory":""}} + ```tool_response + build.gradle + settings.gradle + ``` + {"tool":"run_app","args":{}} + """.trimIndent() + + @Test + fun givenAReplyThatAnswersItsOwnToolCall_whenExtracting_thenOnlyCallsBeforeTheFakeResultRun() { + val calls = ToolCallExtractor.extractToolCalls(hallucinatedTranscript) + + assertEquals(1, calls.size) + assertEquals("read_build_output", calls[0].name) + } + + @Test + fun givenAReplyThatAnswersItsOwnToolCall_whenReadingTheProse_thenTheInventedTranscriptIsHidden() { + val prose = ToolCallExtractor.proseOutsideToolCalls(hallucinatedTranscript) + + assertNull(prose) + } + + @Test + fun givenAFabricatedResultInATag_whenExtracting_thenItTruncatesTheSameWayAsAFence() { + val calls = ToolCallExtractor.extractToolCalls( + """ + {"tool":"read_file","args":{"file_path":"A.kt"}} + class A + {"tool":"edit_file","args":{"file_path":"A.kt"}} + """.trimIndent() + ) + + assertEquals(1, calls.size) + assertEquals("read_file", calls[0].name) + } + + @Test + fun givenAReplyWithNoFabricatedResult_whenExtracting_thenEveryCallSurvives() { + val calls = ToolCallExtractor.extractToolCalls( + """ + {"tool":"read_file","args":{"file_path":"A.kt"}} + {"tool":"read_file","args":{"file_path":"B.kt"}} + """.trimIndent() + ) + + assertEquals(2, calls.size) + } } diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt new file mode 100644 index 00000000..460fd28d --- /dev/null +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt @@ -0,0 +1,194 @@ +package com.itsaky.androidide.plugins.aicore.tool.handlers + +import com.itsaky.androidide.plugins.PluginContext +import com.itsaky.androidide.plugins.ServiceRegistry +import com.itsaky.androidide.plugins.services.IdeBuildService +import io.mockk.every +import io.mockk.mockk +import kotlinx.coroutines.test.runTest +import org.junit.Assert.assertFalse +import org.junit.Assert.assertTrue +import org.junit.Before +import org.junit.Test + +/** + * Unit tests for [ReadBuildOutputHandler] — the tool that hands the agent the build log. + * Covers the 8000-character budget and the error-anchored window that replaced a plain tail, + * which lost the compiler errors behind Gradle's closing summary. + */ +class ReadBuildOutputHandlerTest { + + private lateinit var context: PluginContext + private lateinit var services: ServiceRegistry + private lateinit var buildService: IdeBuildService + private lateinit var handler: ReadBuildOutputHandler + + @Before + fun setup() { + buildService = mockk(relaxed = true) + services = mockk() + context = mockk() + every { context.services } returns services + every { services.get(IdeBuildService::class.java) } returns buildService + handler = ReadBuildOutputHandler(context) + } + + /** Gradle chatter that must never be mistaken for an error line. */ + private fun noise(lines: Int, label: String = "step"): String = + (1..lines).joinToString("\n") { "> Task :app:$label$it" } + + @Test + fun givenNoBuildService_whenReading_thenItFails() = runTest { + every { services.get(IdeBuildService::class.java) } returns null + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertTrue(result.message.contains("not available")) + } + + @Test + fun givenNullOutput_whenReading_thenItReportsNoOutput() = runTest { + every { buildService.getBuildOutput() } returns null + + val result = handler.execute(emptyMap()) + + assertTrue(result.success) + assertTrue(result.message.contains("No build output")) + } + + @Test + fun givenBlankOutput_whenReading_thenItReportsNoOutput() = runTest { + every { buildService.getBuildOutput() } returns " \n\n " + + val result = handler.execute(emptyMap()) + + assertTrue(result.success) + assertTrue(result.message.contains("No build output")) + } + + @Test + fun givenShortCleanOutput_whenReading_thenItIsReturnedUnchanged() = runTest { + val output = "> Task :app:assembleDebug\nBUILD SUCCESSFUL in 4s\n" + every { buildService.getBuildOutput() } returns output + + val result = handler.execute(emptyMap()) + + assertTrue(result.success) + assertTrue(result.data == output) + assertFalse(result.data.orEmpty().contains("truncated")) + } + + @Test + fun givenOutputLongerThanTheLimit_whenReading_thenItIsCappedAtTheLimit() = runTest { + val output = noise(2000) + assertTrue("fixture must exceed the budget", output.length > ReadBuildOutputHandler.MAX_OUTPUT_CHARS) + every { buildService.getBuildOutput() } returns output + + val result = handler.execute(emptyMap()) + + val data = result.data.orEmpty() + assertTrue(result.success) + assertTrue(data.startsWith("...[truncated]...")) + assertTrue(data.contains("> Task :app:step2000")) + assertFalse("the head must be dropped", data.contains("> Task :app:step1\n")) + } + + @Test + fun givenNoErrorInALongLog_whenReading_thenItReturnsThePlainTail() = runTest { + every { buildService.getBuildOutput() } returns noise(2000) + "\nBUILD SUCCESSFUL in 41s" + + val result = handler.execute(emptyMap()) + + assertTrue(result.data.orEmpty().endsWith("BUILD SUCCESSFUL in 41s")) + assertTrue(result.message.contains("last")) + } + + @Test + fun givenAKotlinErrorEarlyInALongLog_whenReading_thenTheWindowStartsAtThatError() = runTest { + val error = "e: file:///project/app/src/main/java/Main.kt:12:5 unresolved reference: foo" + every { buildService.getBuildOutput() } returns + noise(500) + "\n" + error + "\n" + noise(20, label = "tail") + "\nBUILD FAILED in 9s" + + val result = handler.execute(emptyMap()) + + val data = result.data.orEmpty() + assertTrue("the error must survive", data.contains(error)) + assertFalse("the head must be dropped", data.contains("> Task :app:step1\n")) + assertTrue(data.endsWith("BUILD FAILED in 9s")) + assertTrue(result.message.contains("first error")) + } + + @Test + fun givenAWarningBeforeAnError_whenReading_thenItAnchorsOnTheErrorNotTheWarning() = runTest { + val warning = "w: file:///project/app/src/main/java/Main.kt:3:1 unused variable" + val error = "e: file:///project/app/src/main/java/Main.kt:12:5 unresolved reference: foo" + every { buildService.getBuildOutput() } returns "$warning\n$error\nBUILD FAILED in 9s" + + val data = handler.execute(emptyMap()).data.orEmpty() + + assertFalse("a warning must not anchor the window", data.contains(warning)) + assertTrue(data.startsWith("...[truncated]...\n$error")) + } + + @Test + fun givenAGradleTaskFailure_whenReading_thenTheWindowStartsAtTheFailureBanner() = runTest { + val banner = "FAILURE: Build failed with an exception." + every { buildService.getBuildOutput() } returns + noise(400) + "\n" + banner + "\n* What went wrong:\nExecution failed for task ':app:compileDebugKotlin'." + + val data = handler.execute(emptyMap()).data.orEmpty() + + assertTrue(data.contains(banner)) + assertFalse(data.contains("> Task :app:step1\n")) + } + + @Test + fun givenAJavacError_whenReading_thenTheWindowStartsAtThatError() = runTest { + val error = "/project/app/src/main/java/Main.java:12: error: cannot find symbol" + every { buildService.getBuildOutput() } returns noise(300) + "\n" + error + "\nBUILD FAILED" + + val data = handler.execute(emptyMap()).data.orEmpty() + + assertTrue(data.contains(error)) + assertFalse(data.contains("> Task :app:step1\n")) + } + + @Test + fun givenTimingPrefixedLines_whenReading_thenTheErrorIsStillFound() = runTest { + val error = "[10:31:02.412] Δ12ms e: file:///project/Main.kt:12:5 unresolved reference: foo" + every { buildService.getBuildOutput() } returns + "[10:31:01.000] Δ4ms > Task :app:compileDebugKotlin\n" + error + "\nBUILD FAILED" + + val data = handler.execute(emptyMap()).data.orEmpty() + + assertTrue(data.contains(error)) + assertFalse(data.contains("compileDebugKotlin")) + } + + @Test + fun givenHundredsOfErrors_whenReading_thenItStillEndsAtTheSummary() = runTest { + val errors = (1..2000).joinToString("\n") { "e: file:///project/File$it.kt:1:1 unresolved reference" } + every { buildService.getBuildOutput() } returns errors + "\nBUILD FAILED in 12s" + + val result = handler.execute(emptyMap()) + + val data = result.data.orEmpty() + assertTrue(data.endsWith("BUILD FAILED in 12s")) + assertTrue(data.startsWith("...[truncated]...")) + assertTrue( + "budget exceeded: ${data.length}", + data.length <= ReadBuildOutputHandler.MAX_OUTPUT_CHARS + "...[truncated]...\n".length, + ) + } + + @Test + fun givenTheServiceThrows_whenReading_thenItFailsWithoutPropagating() = runTest { + every { buildService.getBuildOutput() } throws IllegalStateException("boom") + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertTrue(result.error_details.orEmpty().contains("boom")) + } +} diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt new file mode 100644 index 00000000..28fe179f --- /dev/null +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt @@ -0,0 +1,166 @@ +package com.itsaky.androidide.plugins.aicore.tool.handlers + +import com.itsaky.androidide.plugins.PluginContext +import com.itsaky.androidide.plugins.ServiceRegistry +import com.itsaky.androidide.plugins.services.BuildAndLaunchCallback +import com.itsaky.androidide.plugins.aicore.models.ToolResult +import com.itsaky.androidide.plugins.services.IdeBuildService +import io.mockk.Runs +import io.mockk.every +import io.mockk.just +import io.mockk.mockk +import io.mockk.verify +import kotlinx.coroutines.cancelAndJoin +import kotlinx.coroutines.launch +import kotlinx.coroutines.test.runCurrent +import kotlinx.coroutines.test.runTest +import org.junit.Assert.assertEquals +import org.junit.Assert.assertFalse +import org.junit.Assert.assertNull +import org.junit.Assert.assertTrue +import org.junit.Before +import org.junit.Test + +/** + * Unit tests for [RunAppHandler] — the tool that builds and launches the app. Covers the wait for + * [BuildAndLaunchCallback] that replaced fire-and-forget, which reported success roughly a second + * after the build started and long before it could have failed. + */ +class RunAppHandlerTest { + + private lateinit var context: PluginContext + private lateinit var services: ServiceRegistry + private lateinit var buildService: IdeBuildService + private lateinit var handler: RunAppHandler + + @Before + fun setup() { + buildService = mockk(relaxed = true) + services = mockk() + context = mockk() + every { context.services } returns services + every { services.get(IdeBuildService::class.java) } returns buildService + every { buildService.isBuildInProgress() } returns false + handler = RunAppHandler(context) + } + + /** Stubs `runApp` to invoke its callback synchronously, as the host does on several paths. */ + private fun answerWith(vararg outcomes: Pair) { + every { buildService.runApp(any()) } answers { + val callback = firstArg() + outcomes.forEach { (success, message) -> callback.onComplete(success, message) } + } + } + + @Test + fun givenNoBuildService_whenRunning_thenItFails() = runTest { + every { services.get(IdeBuildService::class.java) } returns null + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertTrue(result.message.contains("not available")) + } + + @Test + fun givenABuildAlreadyInProgress_whenRunning_thenItFailsWithoutTriggeringAnother() = runTest { + every { buildService.isBuildInProgress() } returns true + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertTrue(result.message.contains("already running")) + verify(exactly = 0) { buildService.runApp(any()) } + } + + @Test + fun givenTheCallbackReportsSuccess_whenRunning_thenItReturnsSuccessWithTheMessage() = runTest { + answerWith(true to "Build successful") + + val result = handler.execute(emptyMap()) + + assertTrue(result.success) + assertEquals("Build succeeded", result.message) + assertEquals("Build successful", result.data) + } + + @Test + fun givenTheCallbackReportsFailure_whenRunning_thenItReturnsFailureCarryingTheMessage() = runTest { + answerWith(false to "Build failed: compilation error") + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertEquals("Build failed", result.message) + assertTrue(result.error_details.orEmpty().contains("compilation error")) + assertTrue( + "the agent must be pointed at the log", + result.error_details.orEmpty().contains("read_build_output"), + ) + } + + @Test + fun givenTheCallbackNeverFires_whenRunning_thenItReportsBuildStillRunning() = runTest { + every { buildService.runApp(any()) } just Runs + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertEquals("Build still running", result.message) + assertTrue(result.error_details.orEmpty().contains("read_build_output")) + } + + @Test + fun givenTheCallbackFiresTwice_whenRunning_thenTheFirstOutcomeWinsWithoutCrashing() = runTest { + answerWith(true to "first", false to "second") + + val result = handler.execute(emptyMap()) + + assertTrue(result.success) + assertEquals("first", result.data) + } + + @Test + fun givenRunAppThrows_whenRunning_thenItReportsTheErrorWithoutPropagating() = runTest { + every { buildService.runApp(any()) } throws IllegalStateException("tooling server gone") + + val result = handler.execute(emptyMap()) + + assertFalse(result.success) + assertTrue(result.message.contains("IllegalStateException")) + assertTrue(result.error_details.orEmpty().contains("tooling server gone")) + } + + @Test + fun givenTheCallerIsCancelled_whenWaitingForTheBuild_thenTheCancellationUnwinds() = runTest { + // Stop must interrupt the wait. Swallowed into a ToolResult it reads as a build failure, + // and the agent loop carries on with the run the user just stopped. + every { buildService.runApp(any()) } just Runs + var result: ToolResult? = null + + val job = launch { result = handler.execute(emptyMap()) } + runCurrent() + job.cancelAndJoin() + + assertNull("a cancelled run must produce no result", result) + } + + @Test + fun givenTheToolDescription_whenReadByTheModel_thenItSaysTheInstallNeedsTheUser() { + // The host completes the callback when the installer takes the APK, before the system + // install prompt is answered. Without this caveat the model reports the app as running. + assertTrue( + "run_app success does not mean the app launched", + handler.description.contains("install started"), + ) + } + + @Test + fun givenABuildThatIsNotInProgress_whenRunning_thenItTriggersExactlyOneBuild() = runTest { + answerWith(true to "Build successful") + + handler.execute(emptyMap()) + + verify(exactly = 1) { buildService.runApp(any()) } + } +} diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStoreTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStoreTest.kt new file mode 100644 index 00000000..c7061d59 --- /dev/null +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/viewmodel/ChatViewModelStoreTest.kt @@ -0,0 +1,49 @@ +package com.itsaky.androidide.plugins.aicore.viewmodel + +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.ExperimentalCoroutinesApi +import kotlinx.coroutines.test.UnconfinedTestDispatcher +import kotlinx.coroutines.test.resetMain +import kotlinx.coroutines.test.setMain +import org.junit.After +import org.junit.Assert.assertNotSame +import org.junit.Assert.assertSame +import org.junit.Before +import org.junit.Test + +/** + * Guards the retention contract behind the tab-switch fix: the Agent tab's ViewModel — and with it + * the run in flight — must outlive the fragment the host removes on every tab switch. + */ +@OptIn(ExperimentalCoroutinesApi::class) +class ChatViewModelStoreTest { + + @Before + fun setUp() { + // ChatViewModel's stateIn() calls run on viewModelScope, i.e. Dispatchers.Main. + Dispatchers.setMain(UnconfinedTestDispatcher()) + } + + @After + fun tearDown() { + ChatViewModelStore.clear() + Dispatchers.resetMain() + } + + @Test + fun givenTheAgentTabIsReopened_whenTheViewModelIsResolved_thenTheSameInstanceComesBack() { + val fromFirstFragment = ChatViewModelStore.get() + val fromSecondFragment = ChatViewModelStore.get() + + assertSame(fromFirstFragment, fromSecondFragment) + } + + @Test + fun givenARetainedViewModel_whenTheStoreIsCleared_thenTheNextResolveBuildsANewOne() { + val beforeDispose = ChatViewModelStore.get() + + ChatViewModelStore.clear() + + assertNotSame(beforeDispose, ChatViewModelStore.get()) + } +} From 8477448e78d81a1198de6865344fdced09550765 Mon Sep 17 00:00:00 2001 From: John Trujillo Date: Wed, 2 Sep 2026 08:59:49 -0500 Subject: [PATCH 2/2] fix(ai): move status-line strings to resources and drop duplicate handler logs AgentState now exposes stepNumber/estimatedTotalMillis with ChatFragment rendering them via getString; handlers log once through AgentTrace plus pluginContext.logger. --- .../plugins/aicore/fragments/ChatFragment.kt | 38 +++- .../plugins/aicore/models/AgentState.kt | 41 ++--- .../plugins/aicore/tool/ToolCallExtractor.kt | 10 +- .../tool/handlers/ReadBuildOutputHandler.kt | 19 +- .../aicore/tool/handlers/RunAppHandler.kt | 19 +- ai-core/src/main/res/values/strings.xml | 3 +- .../aicore/models/AgentStateExecutingTest.kt | 165 +++--------------- .../aicore/models/ChatViewModelTimerTest.kt | 28 ++- .../handlers/ReadBuildOutputHandlerTest.kt | 2 + .../aicore/tool/handlers/RunAppHandlerTest.kt | 2 + 10 files changed, 112 insertions(+), 215 deletions(-) diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt index 8c88698c..1ea7ed9a 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/fragments/ChatFragment.kt @@ -37,6 +37,7 @@ import com.itsaky.androidide.plugins.services.IdeTooltipService import com.itsaky.androidide.plugins.services.IdeUIService import io.noties.markwon.Markwon import java.io.File +import java.util.concurrent.TimeUnit import kotlinx.coroutines.launch private const val TAG = "$LOG_PREFIX.ChatFragment" @@ -412,9 +413,10 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { // token, and a per-message dump here made the log unreadable during a run. if (messages.size != renderedMessageCount) { renderedMessageCount = messages.size - android.util.Log.d( - TAG, - "rendering $renderedMessageCount messages, last=${messages.lastOrNull()?.sender}" + AgentTrace.detail( + "UI", + "rendering messages=$renderedMessageCount " + + "last=${messages.lastOrNull()?.sender}" ) } binding.emptyChatView.isVisible = messages.isEmpty() @@ -440,8 +442,17 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { is AgentState.Idle -> binding.agentStatusContainer.isVisible = false is AgentState.Executing -> { binding.agentStatusContainer.isVisible = true - binding.agentStatusMessage.text = state.formattedProgress - binding.agentStatusTimer.text = state.formattedTiming + binding.agentStatusMessage.text = getString( + R.string.state_executing, + state.stepNumber, + state.totalSteps, + state.description, + ) + binding.agentStatusTimer.text = getString( + R.string.state_executing_timing, + formatDuration(state.elapsedMillis), + formatDuration(state.estimatedTotalMillis), + ) viewModel.startStateTimer(state) } is AgentState.Processing -> { @@ -464,6 +475,23 @@ class ChatFragment : Fragment(), ApprovalDialogFragment.Host { } } + /** + * Renders a duration the way the status timer reads it: `4.5s`, or `1m 4.5s` past the minute. + * + * @param millis the duration; a clock that ran backwards reads as zero. + * @return the localised figure, with no surrounding words. + */ + private fun formatDuration(millis: Long): String { + val total = millis.coerceAtLeast(0) + val minutes = TimeUnit.MILLISECONDS.toMinutes(total) + val seconds = (total - TimeUnit.MINUTES.toMillis(minutes)) / 1000.0 + return if (minutes > 0) { + getString(R.string.time_format_minutes, minutes, seconds) + } else { + getString(R.string.time_format_seconds, seconds) + } + } + /** * The approval dialog currently on screen, looked up by tag rather than held in a field: * after a configuration change this fragment is a new instance, and a field would be null diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt index ab14509b..34674f85 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentState.kt @@ -29,36 +29,20 @@ sealed class AgentState { val startTime: Long = System.currentTimeMillis(), val elapsedMillis: Long = 0 ) : AgentState() { - val formattedProgress: String - get() = "Step ${currentStepIndex + 1} of $totalSteps: $description" + /** Step number as the status line counts it, from 1. */ + val stepNumber: Int + get() = currentStepIndex + 1 - val formattedTiming: String + /** + * Projected duration of the whole run, from the average time per step so far. The words + * around these figures are resources, so the rendering itself belongs to the UI layer. + */ + val estimatedTotalMillis: Long get() { - val elapsed = formatTime(elapsedMillis) - // Estimate total time based on average time per step - val estimatedTotal = if (currentStepIndex > 0) { - val avgPerStep = elapsedMillis / (currentStepIndex + 1) - avgPerStep * totalSteps - } else { - elapsedMillis * totalSteps - } - val total = formatTime(estimatedTotal) - return "($elapsed of $total)" + // A device clock change can put the elapsed time behind the start. + val elapsed = elapsedMillis.coerceAtLeast(0) + return (elapsed / stepNumber) * totalSteps } - - private fun formatTime(millis: Long): String { - if (millis < 0) return "0.0s" - val minutes = java.util.concurrent.TimeUnit.MILLISECONDS.toMinutes(millis) - val seconds = java.util.concurrent.TimeUnit.MILLISECONDS.toSeconds(millis) - - java.util.concurrent.TimeUnit.MINUTES.toSeconds(minutes) - val remainingMillis = millis % 1000 - val totalSeconds = seconds + (remainingMillis / 1000.0) - return if (minutes > 0) { - String.format(java.util.Locale.US, "%dm %.1fs", minutes, totalSeconds) - } else { - String.format(java.util.Locale.US, "%.1fs", totalSeconds) - } - } } /** @@ -79,7 +63,8 @@ sealed class AgentState { /** * Short name for the trace log: the state and what it is doing, without a data class's field dump - * and without the error text, which is already in the transcript. + * and without the error text, which is already in the transcript. Logcat only — nothing here + * reaches the UI, which renders each state from string resources. */ val AgentState.traceLabel: String get() = when (this) { diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt index 9b67e3bf..69a9890d 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/ToolCallExtractor.kt @@ -1,6 +1,7 @@ package com.itsaky.androidide.plugins.aicore.tool import android.util.Log +import com.itsaky.androidide.plugins.aicore.logging.AgentTrace import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import org.json.JSONObject @@ -37,10 +38,11 @@ class ToolCallExtractor { */ internal fun beforeFabricatedResult(text: String): String { val match = FABRICATED_RESULT_REGEX.find(text) ?: return text - Log.w( - TAG, - "Reply writes its own tool result at offset ${match.range.first}; " + - "ignoring the ${text.length - match.range.first} chars after it", + AgentTrace.refusal( + "PARSE", + "fabricated tool result offset=${match.range.first} " + + "ignoredChars=${text.length - match.range.first}", + "the reply answered its own tool call" ) return text.substring(0, match.range.first) } diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt index 0feb318d..331a0c9c 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandler.kt @@ -1,16 +1,12 @@ package com.itsaky.androidide.plugins.aicore.tool.handlers -import android.util.Log import com.itsaky.androidide.plugins.PluginContext import com.itsaky.androidide.plugins.aicore.logging.AgentTrace -import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import com.itsaky.androidide.plugins.aicore.models.ToolResult import com.itsaky.androidide.plugins.aicore.tool.ToolHandler import com.itsaky.androidide.plugins.services.IdeBuildService import kotlinx.coroutines.CancellationException -private const val TAG = "$LOG_PREFIX.ReadBuildOutputHandler" - /** The slice of a build log handed to the model, and whether it starts at the first error. */ internal data class OutputWindow( val text: String, @@ -28,12 +24,14 @@ class ReadBuildOutputHandler( override val requiresApproval = false override suspend fun execute(args: Map): ToolResult { - Log.d(TAG, "Reading build output") - return try { val buildService = pluginContext.services.get(IdeBuildService::class.java) if (buildService == null) { - Log.w(TAG, "IdeBuildService not available") + AgentTrace.refusal( + "BUILD", + "read_build_output rejected", + "IdeBuildService not available" + ) return ToolResult.failure( "Build service not available", "The IDE build service is not available." @@ -42,7 +40,6 @@ class ReadBuildOutputHandler( val output = buildService.getBuildOutput() if (output.isNullOrBlank()) { - Log.d(TAG, "No build output available") AgentTrace.detail("BUILD", "read_build_output chars=0 (host returned nothing)") ToolResult.success( message = "No build output available", @@ -50,7 +47,6 @@ class ReadBuildOutputHandler( ) } else { val window = windowFor(output) - Log.d(TAG, "Read ${window.text.length} chars, anchored=${window.anchoredOnError}") AgentTrace.detail( "BUILD", "read_build_output chars=${window.text.length} " + @@ -69,7 +65,10 @@ class ReadBuildOutputHandler( // An Exception on the JVM, so the catch below would report Stop as a read failure. throw ce } catch (e: Exception) { - Log.e(TAG, "Error reading build output", e) + // The trace stream keeps the run readable; the host log keeps the stack trace, which + // AgentTrace previews only in a debug build. + AgentTrace.refusal("BUILD", "read_build_output failed", e.toString()) + pluginContext.logger.error("read_build_output failed", e) ToolResult.failure( "Error reading build output", "${e.message ?: "Unknown error"}\n\n${e.stackTraceToString()}" diff --git a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt index 8a9ae41f..bb10dc8d 100644 --- a/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt +++ b/ai-core/src/main/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandler.kt @@ -1,9 +1,7 @@ package com.itsaky.androidide.plugins.aicore.tool.handlers -import android.util.Log import com.itsaky.androidide.plugins.PluginContext import com.itsaky.androidide.plugins.aicore.logging.AgentTrace -import com.itsaky.androidide.plugins.aicore.logging.LOG_PREFIX import com.itsaky.androidide.plugins.aicore.models.ToolResult import com.itsaky.androidide.plugins.aicore.tool.ToolHandler import com.itsaky.androidide.plugins.services.BuildAndLaunchCallback @@ -17,8 +15,6 @@ import kotlinx.coroutines.withTimeoutOrNull import java.util.concurrent.atomic.AtomicBoolean import kotlin.coroutines.resume -private const val TAG = "$LOG_PREFIX.RunAppHandler" - /** How long to wait for the build callback before reporting the build still running. */ internal const val BUILD_TIMEOUT_MS = 10 * 60 * 1000L @@ -49,7 +45,7 @@ class RunAppHandler( return try { val buildService = pluginContext.services.get(IdeBuildService::class.java) if (buildService == null) { - Log.w(TAG, "IdeBuildService not available - service is null") + AgentTrace.refusal("BUILD", "run_app rejected", "IdeBuildService not available") return ToolResult.failure( "Build service not available", "The IDE build service is not available. This IDE instance may not support build operations." @@ -57,14 +53,13 @@ class RunAppHandler( } if (buildService.isBuildInProgress()) { - Log.d(TAG, "A build is already in progress") + AgentTrace.refusal("BUILD", "run_app rejected", "a build is already in progress") return ToolResult.failure( "Build already running", "A build is already in progress. Please wait for it to complete before running again." ) } - Log.d(TAG, "Triggering app build and launch...") AgentTrace.stage("BUILD", "run_app triggered; waiting for the build callback") val startMs = System.currentTimeMillis() val outcome = withTimeoutOrNull(BUILD_TIMEOUT_MS) { @@ -80,7 +75,6 @@ class RunAppHandler( val waitedMs = System.currentTimeMillis() - startMs if (outcome == null) { - Log.w(TAG, "Build did not report back within $BUILD_TIMEOUT_MS ms") AgentTrace.refusal( "BUILD", "run_app timed out waitedMs=$waitedMs", @@ -100,13 +94,11 @@ class RunAppHandler( AgentTrace.preview(message) ) if (success) { - Log.i(TAG, "Build succeeded: $message") ToolResult.success( message = "Build succeeded", data = message ) } else { - Log.w(TAG, "Build failed: $message") ToolResult.failure( "Build failed", "$message\n\nCall read_build_output for the compiler errors." @@ -116,7 +108,10 @@ class RunAppHandler( // An Exception on the JVM, so the catch below would report Stop as a build failure. throw ce } catch (e: Exception) { - Log.e(TAG, "Exception in run app tool", e) + // The trace stream keeps the run readable; the host log keeps the stack trace, which + // AgentTrace previews only in a debug build. + AgentTrace.refusal("BUILD", "run_app failed", e.toString()) + pluginContext.logger.error("run_app failed", e) ToolResult.failure( "Error: ${e.javaClass.simpleName}", "${e.message ?: "Unknown error"}\n\n${e.stackTraceToString()}" @@ -158,7 +153,7 @@ class RunAppHandler( try { buildService.runApp(callback) } catch (e: Exception) { - Log.e(TAG, "Failed to trigger build", e) + // Reported to the caller, which logs it once with the stack trace. if (reported.compareAndSet(false, true)) { continuation.resumeWith(Result.failure(e)) } diff --git a/ai-core/src/main/res/values/strings.xml b/ai-core/src/main/res/values/strings.xml index 41378167..23308cdb 100644 --- a/ai-core/src/main/res/values/strings.xml +++ b/ai-core/src/main/res/values/strings.xml @@ -27,7 +27,8 @@ Initializing… Thinking… Processing… - Executing step %1$d of %2$d: %3$s + Step %1$d of %2$d: %3$s + (%1$s of %2$s) Cancelling… diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentStateExecutingTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentStateExecutingTest.kt index 24693830..2964e675 100644 --- a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentStateExecutingTest.kt +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/AgentStateExecutingTest.kt @@ -1,16 +1,18 @@ package com.itsaky.androidide.plugins.aicore.models +import org.junit.Assert.assertEquals +import org.junit.Assert.assertNotNull import org.junit.Test -import org.junit.Assert.* -import java.util.concurrent.TimeUnit /** - * Unit tests for AgentState.Executing with step progress and timing. + * Unit tests for [AgentState.Executing] — the step counter and the timing estimate behind the + * status line. The words around those figures are string resources rendered by the fragment, so + * what is testable here is the arithmetic. */ class AgentStateExecutingTest { @Test - fun testExecutingStateCreation() { + fun givenAFreshState_whenCreated_thenItCarriesTheStepAndNoElapsedTime() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 5, @@ -25,40 +27,14 @@ class AgentStateExecutingTest { } @Test - fun testFormattedProgressFirstStep() { - val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 5, - description = "Reading file" - ) - - assertEquals("Step 1 of 5: Reading file", state.formattedProgress) + fun givenAStepIndex_whenCounted_thenTheStepNumberIsOneBased() { + assertEquals(1, AgentState.Executing(0, 5, "First").stepNumber) + assertEquals(3, AgentState.Executing(2, 5, "Middle").stepNumber) + assertEquals(5, AgentState.Executing(4, 5, "Last").stepNumber) } @Test - fun testFormattedProgressMiddleStep() { - val state = AgentState.Executing( - currentStepIndex = 2, - totalSteps = 5, - description = "Processing data" - ) - - assertEquals("Step 3 of 5: Processing data", state.formattedProgress) - } - - @Test - fun testFormattedProgressLastStep() { - val state = AgentState.Executing( - currentStepIndex = 4, - totalSteps = 5, - description = "Finalizing" - ) - - assertEquals("Step 5 of 5: Finalizing", state.formattedProgress) - } - - @Test - fun testFormattedTimingWithZeroElapsed() { + fun givenNoElapsedTime_whenEstimating_thenTheTotalIsZero() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 5, @@ -66,13 +42,11 @@ class AgentStateExecutingTest { elapsedMillis = 0 ) - val timing = state.formattedTiming - assertTrue(timing.contains("0.0s")) - assertTrue(timing.contains("of")) + assertEquals(0L, state.estimatedTotalMillis) } @Test - fun testFormattedTimingWithMilliseconds() { + fun givenTheFirstStep_whenEstimating_thenItProjectsThatStepAcrossAllOfThem() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 5, @@ -80,60 +54,24 @@ class AgentStateExecutingTest { elapsedMillis = 500 ) - val timing = state.formattedTiming - assertTrue(timing.contains("s")) - assertTrue(timing.contains("of")) - // Should show 0.5s or similar - } - - @Test - fun testFormattedTimingWithSeconds() { - val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 5, - description = "Reading file", - elapsedMillis = 2500 - ) - - val timing = state.formattedTiming - assertTrue(timing.contains("s")) - assertTrue(timing.contains("of")) + assertEquals(2500L, state.estimatedTotalMillis) } @Test - fun testFormattedTimingWithMinutesAndSeconds() { + fun givenTwoStepsDone_whenEstimating_thenItProjectsTheAveragePerStep() { + // 2000ms over 2 steps is 1000ms a step, so 5 steps is 5000ms. val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 5, - description = "Reading file", - elapsedMillis = 65000 // 1 minute 5 seconds - ) - - val timing = state.formattedTiming - assertTrue(timing.contains("m")) - assertTrue(timing.contains("s")) - assertTrue(timing.contains("of")) - } - - @Test - fun testFormattedTimingEstimateWithMultipleSteps() { - // Simulate 2 steps completed out of 5 - // If 2000ms elapsed for 2 steps, avg is 1000ms per step - // Estimated total should be around 5000ms - val state = AgentState.Executing( - currentStepIndex = 1, // 2nd step (0-indexed) + currentStepIndex = 1, totalSteps = 5, description = "Processing", elapsedMillis = 2000 ) - val timing = state.formattedTiming - assertTrue(timing.contains("of")) - // Should show estimated total of ~5 seconds + assertEquals(5000L, state.estimatedTotalMillis) } @Test - fun testFormattedTimingNegativeElapsed() { + fun givenAClockThatRanBackwards_whenEstimating_thenTheTotalIsZeroRatherThanNegative() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 5, @@ -141,12 +79,11 @@ class AgentStateExecutingTest { elapsedMillis = -100 ) - val timing = state.formattedTiming - assertTrue(timing.contains("0.0s")) + assertEquals(0L, state.estimatedTotalMillis) } @Test - fun testExecutingStateCopyWithNewElapsed() { + fun givenAnExistingState_whenCopiedWithNewElapsedTime_thenTheOriginalIsUntouched() { val originalState = AgentState.Executing( currentStepIndex = 0, totalSteps = 5, @@ -156,19 +93,15 @@ class AgentStateExecutingTest { val copiedState = originalState.copy(elapsedMillis = 1000) - assertEquals(0, originalState.currentStepIndex) - assertEquals(5, originalState.totalSteps) - assertEquals("Reading file", originalState.description) assertEquals(0, originalState.elapsedMillis) - - assertEquals(0, copiedState.currentStepIndex) - assertEquals(5, copiedState.totalSteps) - assertEquals("Reading file", copiedState.description) assertEquals(1000, copiedState.elapsedMillis) + assertEquals(originalState.currentStepIndex, copiedState.currentStepIndex) + assertEquals(originalState.totalSteps, copiedState.totalSteps) + assertEquals(originalState.description, copiedState.description) } @Test - fun testExecutingStateWithCustomStartTime() { + fun givenACustomStartTime_whenCreated_thenItIsKeptAsPassed() { val customStartTime = System.currentTimeMillis() - 10000 val state = AgentState.Executing( currentStepIndex = 0, @@ -183,56 +116,14 @@ class AgentStateExecutingTest { } @Test - fun testFormattedProgressWithSpecialCharacters() { + fun givenADescriptionWithPunctuation_whenRead_thenItIsPassedThroughUnchanged() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 2, description = "Read: app/src/main.kt" ) - assertEquals("Step 1 of 2: Read: app/src/main.kt", state.formattedProgress) - } - - @Test - fun testFormattedTimingFormat() { - val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 10, - description = "Processing", - elapsedMillis = 1500 - ) - - val timing = state.formattedTiming - // Should match pattern like "(1.5s of 15.0s)" - assertTrue(timing.startsWith("(")) - assertTrue(timing.endsWith(")")) - assertTrue(timing.contains("of")) - } - - @Test - fun testFormattedTimingWith60Seconds() { - val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 5, - description = "Reading file", - elapsedMillis = 60000 // Exactly 1 minute - ) - - val timing = state.formattedTiming - assertTrue(timing.contains("m")) - assertTrue(timing.contains("s")) - } - - @Test - fun testFormattedTimingWith3Minutes() { - val state = AgentState.Executing( - currentStepIndex = 0, - totalSteps = 5, - description = "Reading file", - elapsedMillis = 180000 // 3 minutes - ) - - val timing = state.formattedTiming - assertTrue(timing.contains("3m")) + assertEquals("Read: app/src/main.kt", state.description) + assertEquals(1, state.stepNumber) } } diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/ChatViewModelTimerTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/ChatViewModelTimerTest.kt index 3b07156a..b7b7b3cf 100644 --- a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/ChatViewModelTimerTest.kt +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/models/ChatViewModelTimerTest.kt @@ -99,21 +99,20 @@ class ChatViewModelTimerTest { } @Test - fun testFormattedProgressFormat() { + fun givenAStepInFlight_whenReadForTheStatusLine_thenItExposesTheStepAndItsDescription() { val state = AgentState.Executing( currentStepIndex = 0, totalSteps = 3, description = "Loading model" ) - val formattedProgress = state.formattedProgress - assertTrue(formattedProgress.contains("Step")) - assertTrue(formattedProgress.contains("of")) - assertTrue(formattedProgress.contains("Loading model")) + assertEquals(1, state.stepNumber) + assertEquals(3, state.totalSteps) + assertEquals("Loading model", state.description) } @Test - fun testFormattedTimingFormat() { + fun givenAStepInFlight_whenTheTimerTicks_thenTheEstimateFollowsTheAveragePerStep() { val state = AgentState.Executing( currentStepIndex = 1, totalSteps = 3, @@ -121,21 +120,14 @@ class ChatViewModelTimerTest { elapsedMillis = 2000 ) - val formattedTiming = state.formattedTiming - assertTrue(formattedTiming.startsWith("(")) - assertTrue(formattedTiming.endsWith(")")) - assertTrue(formattedTiming.contains("of")) + assertEquals(3000L, state.estimatedTotalMillis) } @Test - fun testFormattedProgressMultipleSteps() { - val state1 = AgentState.Executing(0, 5, "First") - val state2 = AgentState.Executing(2, 5, "Middle") - val state3 = AgentState.Executing(4, 5, "Last") - - assertEquals("Step 1 of 5: First", state1.formattedProgress) - assertEquals("Step 3 of 5: Middle", state2.formattedProgress) - assertEquals("Step 5 of 5: Last", state3.formattedProgress) + fun givenSeveralSteps_whenCounted_thenEachReportsItsOwnOneBasedNumber() { + assertEquals(1, AgentState.Executing(0, 5, "First").stepNumber) + assertEquals(3, AgentState.Executing(2, 5, "Middle").stepNumber) + assertEquals(5, AgentState.Executing(4, 5, "Last").stepNumber) } @Test diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt index 460fd28d..53c6cb0b 100644 --- a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/ReadBuildOutputHandlerTest.kt @@ -29,6 +29,8 @@ class ReadBuildOutputHandlerTest { services = mockk() context = mockk() every { context.services } returns services + // The handler logs failures through the host logger. + every { context.logger } returns mockk(relaxed = true) every { services.get(IdeBuildService::class.java) } returns buildService handler = ReadBuildOutputHandler(context) } diff --git a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt index 28fe179f..5195df78 100644 --- a/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt +++ b/ai-core/src/test/kotlin/com/itsaky/androidide/plugins/aicore/tool/handlers/RunAppHandlerTest.kt @@ -39,6 +39,8 @@ class RunAppHandlerTest { services = mockk() context = mockk() every { context.services } returns services + // The handler logs failures through the host logger. + every { context.logger } returns mockk(relaxed = true) every { services.get(IdeBuildService::class.java) } returns buildService every { buildService.isBuildInProgress() } returns false handler = RunAppHandler(context)