chore: add AI trace logging, tool preview improvements, and Edit preference

abose · abose · commit 643ca5a28aa4 · 2026-02-19T18:23:40.000+05:30
Add compact trace logging for AI events on both node and browser sides
for debugging without flooding the console. Fix _finishActiveTools to
not override the delayed timeout set by _updateToolIndicator. Add
"receiving N bytes..." fallback preview during tool input streaming.
Instruct model to prefer Edit over Write for existing files via
appendSystemPrompt. Add timestamps to MCP browser console log output.
diff --git a/phoenix-builder-mcp/mcp-tools.js b/phoenix-builder-mcp/mcp-tools.js
@@ -179,7 +179,16 @@ export function registerTools(server, processManager, wsControlServer, phoenixDe
                 const totalEntries = result.totalEntries || entries.length;
                 const matchedEntries = result.matchedEntries != null ? result.matchedEntries : entries.length;
                 const rangeEnd = result.rangeEnd != null ? result.rangeEnd : matchedEntries;
-                let lines = entries.map(e => `[${e.level}] ${e.message}`);
+                let lines = entries.map(e => {
+                    let ts = "";
+                    if (e.timestamp) {
+                        // Show HH:MM:SS.mmm for compact display
+                        const d = new Date(e.timestamp);
+                        ts = d.toTimeString().slice(0, 8) + "." +
+                            String(d.getMilliseconds()).padStart(3, "0") + " ";
+                    }
+                    return `[${ts}${e.level}] ${e.message}`;
+                });
                 let trimmed = 0;
                 if (maxChars > 0) {
                     const trimResult = _trimToCharBudget(lines, maxChars);
diff --git a/src-node/claude-code-agent.js b/src-node/claude-code-agent.js
@@ -202,6 +202,13 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
         maxTurns: 10,
         allowedTools: ["Read", "Edit", "Write", "Glob", "Grep"],
         permissionMode: "acceptEdits",
+        appendSystemPrompt:
+            "When modifying an existing file, always prefer the Edit tool " +
+            "(find-and-replace) instead of the Write tool. The Write tool should ONLY be used " +
+            "to create brand new files that do not exist yet. For existing files, always use " +
+            "multiple Edit calls to make targeted changes rather than rewriting the entire " +
+            "file with Write. This is critical because Write replaces the entire file content " +
+            "which is slow and loses undo history.",
         includePartialMessages: true,
         abortController: currentAbortController,
         hooks: {
@@ -318,7 +325,11 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
         queryOptions.resume = currentSessionId;
     }
 
+    const _log = (...args) => console.log("[AI]", ...args);
+
     try {
+        _log("Query start:", JSON.stringify(prompt).slice(0, 80), "cwd=" + (projectPath || "?"));
+
         const result = queryFn({
             prompt: prompt,
             options: queryOptions
@@ -334,15 +345,23 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
         let toolCounter = 0;
         let lastToolStreamTime = 0;
 
+        // Trace counters (logged at tool/query completion, not per-delta)
+        let toolDeltaCount = 0;
+        let toolStreamSendCount = 0;
+        let textDeltaCount = 0;
+        let textStreamSendCount = 0;
+
         for await (const message of result) {
             // Check abort
             if (signal.aborted) {
+                _log("Aborted");
                 break;
             }
 
             // Capture session_id from first message
             if (message.session_id && !currentSessionId) {
                 currentSessionId = message.session_id;
+                _log("Session:", currentSessionId);
             }
 
             // Handle streaming events
@@ -356,6 +375,10 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
                     activeToolIndex = event.index;
                     activeToolInputJson = "";
                     toolCounter++;
+                    toolDeltaCount = 0;
+                    toolStreamSendCount = 0;
+                    lastToolStreamTime = 0;
+                    _log("Tool start:", activeToolName, "#" + toolCounter);
                     nodeConnector.triggerPeer("aiProgress", {
                         requestId: requestId,
                         toolName: activeToolName,
@@ -369,9 +392,12 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
                     event.delta?.type === "input_json_delta" &&
                     event.index === activeToolIndex) {
                     activeToolInputJson += event.delta.partial_json;
+                    toolDeltaCount++;
                     const now = Date.now();
-                    if (now - lastToolStreamTime >= TEXT_STREAM_THROTTLE_MS) {
+                    if (activeToolInputJson &&
+                        now - lastToolStreamTime >= TEXT_STREAM_THROTTLE_MS) {
                         lastToolStreamTime = now;
+                        toolStreamSendCount++;
                         nodeConnector.triggerPeer("aiToolStream", {
                             requestId: requestId,
                             toolId: toolCounter,
@@ -387,6 +413,7 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
                     activeToolName) {
                     // Final flush of tool stream (bypasses throttle)
                     if (activeToolInputJson) {
+                        toolStreamSendCount++;
                         nodeConnector.triggerPeer("aiToolStream", {
                             requestId: requestId,
                             toolId: toolCounter,
@@ -400,6 +427,9 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
                     } catch (e) {
                         // ignore parse errors
                     }
+                    _log("Tool done:", activeToolName, "#" + toolCounter,
+                        "deltas=" + toolDeltaCount, "sent=" + toolStreamSendCount,
+                        "json=" + activeToolInputJson.length + "ch");
                     nodeConnector.triggerPeer("aiToolInfo", {
                         requestId: requestId,
                         toolName: activeToolName,
@@ -415,9 +445,11 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
                 if (event.type === "content_block_delta" &&
                     event.delta?.type === "text_delta") {
                     accumulatedText += event.delta.text;
+                    textDeltaCount++;
                     const now = Date.now();
                     if (now - lastStreamTime >= TEXT_STREAM_THROTTLE_MS) {
                         lastStreamTime = now;
+                        textStreamSendCount++;
                         nodeConnector.triggerPeer("aiTextStream", {
                             requestId: requestId,
                             text: accumulatedText
@@ -430,6 +462,7 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
 
         // Flush any remaining accumulated text
         if (accumulatedText) {
+            textStreamSendCount++;
             nodeConnector.triggerPeer("aiTextStream", {
                 requestId: requestId,
                 text: accumulatedText
@@ -444,6 +477,9 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
             });
         }
 
+        _log("Complete: tools=" + toolCounter, "edits=" + collectedEdits.length,
+            "textDeltas=" + textDeltaCount, "textSent=" + textStreamSendCount);
+
         // Signal completion
         nodeConnector.triggerPeer("aiComplete", {
             requestId: requestId,
@@ -455,6 +491,7 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
         const isAbort = signal.aborted || /abort/i.test(errMsg);
 
         if (isAbort) {
+            _log("Cancelled");
             // Query was cancelled — clear session so next query starts fresh
             currentSessionId = null;
             nodeConnector.triggerPeer("aiComplete", {
@@ -464,6 +501,8 @@ async function _runQuery(requestId, prompt, projectPath, model, signal) {
             return;
         }
 
+        _log("Error:", errMsg.slice(0, 200));
+
         // If we collected edits before error, send them
         if (collectedEdits.length > 0) {
             nodeConnector.triggerPeer("aiEditResult", {
diff --git a/src/core-ai/AIChatPanel.js b/src/core-ai/AIChatPanel.js
@@ -40,6 +40,10 @@ define(function (require, exports, module) {
     let _hasReceivedContent = false; // tracks if we've received any text/tool in current response
     const _previousContentMap = {}; // filePath → previous content before edit, for undo support
 
+    // --- AI event trace logging (compact, non-flooding) ---
+    let _traceTextChunks = 0;
+    let _traceToolStreamCounts = {}; // toolId → count
+
     // DOM references
     let $panel, $messages, $status, $statusText, $textarea, $sendBtn, $stopBtn;
 
@@ -230,12 +234,17 @@ define(function (require, exports, module) {
         // Get project path
         const projectPath = _getProjectRealPath();
 
+        _traceTextChunks = 0;
+        _traceToolStreamCounts = {};
+        console.log("[AI UI] Sending prompt:", text.slice(0, 60));
+
         _nodeConnector.execPeer("sendPrompt", {
             prompt: text,
             projectPath: projectPath,
             sessionAction: "continue"
         }).then(function (result) {
             _currentRequestId = result.requestId;
+            console.log("[AI UI] RequestId:", result.requestId);
         }).catch(function (err) {
             _setStreaming(false);
             _appendErrorMessage("Failed to send message: " + (err.message || String(err)));
@@ -288,6 +297,11 @@ define(function (require, exports, module) {
     // --- Event handlers for node-side events ---
 
     function _onTextStream(_event, data) {
+        _traceTextChunks++;
+        if (_traceTextChunks === 1) {
+            console.log("[AI UI]", "First text chunk");
+        }
+
         // Remove thinking indicator on first content
         if (!_hasReceivedContent) {
             _hasReceivedContent = true;
@@ -315,6 +329,7 @@ define(function (require, exports, module) {
     };
 
     function _onProgress(_event, data) {
+        console.log("[AI UI]", "Progress:", data.phase, data.toolName ? data.toolName + " #" + data.toolId : "");
         if ($statusText) {
             const toolName = data.toolName || "";
             const config = TOOL_CONFIG[toolName];
@@ -326,11 +341,17 @@ define(function (require, exports, module) {
     }
 
     function _onToolInfo(_event, data) {
+        const uid = (_currentRequestId || "") + "-" + data.toolId;
+        const streamCount = _traceToolStreamCounts[uid] || 0;
+        console.log("[AI UI]", "ToolInfo:", data.toolName, "#" + data.toolId,
+            "file=" + (data.toolInput && data.toolInput.file_path || "?").split("/").pop(),
+            "streamEvents=" + streamCount);
         _updateToolIndicator(data.toolId, data.toolName, data.toolInput);
     }
 
     function _onToolStream(_event, data) {
         const uniqueToolId = (_currentRequestId || "") + "-" + data.toolId;
+        _traceToolStreamCounts[uniqueToolId] = (_traceToolStreamCounts[uniqueToolId] || 0) + 1;
         const $tool = $messages.find('.ai-msg-tool[data-tool-id="' + uniqueToolId + '"]');
         if (!$tool.length) {
             return;
@@ -348,6 +369,10 @@ define(function (require, exports, module) {
         }
 
         const preview = _extractToolPreview(data.toolName, data.partialJson);
+        if (_traceToolStreamCounts[uniqueToolId] === 1) {
+            console.log("[AI UI]", "ToolStream first:", data.toolName, "#" + data.toolId,
+                "json=" + (data.partialJson || "").length + "ch");
+        }
         if (preview) {
             $tool.find(".ai-tool-preview").text(preview);
             _scrollToBottom();
@@ -389,7 +414,8 @@ define(function (require, exports, module) {
         if (!partialJson) {
             return "";
         }
-        // Map tool names to the key whose value we want to preview
+        // Map tool names to the key whose value we want to preview.
+        // Tools not listed here get no streaming preview.
         const interestingKey = {
             Write: "content",
             Edit: "new_string",
@@ -398,19 +424,21 @@ define(function (require, exports, module) {
             Glob: "pattern"
         }[toolName];
 
+        if (!interestingKey) {
+            return "";
+        }
+
         let raw = "";
-        if (interestingKey) {
-            // Find the interesting key and grab everything after it
-            const keyPattern = '"' + interestingKey + '":';
-            const idx = partialJson.indexOf(keyPattern);
-            if (idx !== -1) {
-                raw = partialJson.slice(idx + keyPattern.length).slice(-120);
-            }
-            // If the interesting key hasn't appeared yet, show nothing
-            // rather than raw JSON noise like {"file_path":...
-        } else {
-            // No interesting key defined for this tool — use the tail
-            raw = partialJson.slice(-120);
+        // Find the interesting key and grab everything after it
+        const keyPattern = '"' + interestingKey + '":';
+        const idx = partialJson.indexOf(keyPattern);
+        if (idx !== -1) {
+            raw = partialJson.slice(idx + keyPattern.length).slice(-120);
+        }
+        // If the interesting key hasn't appeared yet, show a byte counter
+        // so the user sees streaming activity during the file_path phase
+        if (!raw && partialJson.length > 3) {
+            return "receiving " + partialJson.length + " bytes...";
         }
         if (!raw) {
             return "";
@@ -430,6 +458,7 @@ define(function (require, exports, module) {
     }
 
     function _onEditResult(_event, data) {
+        console.log("[AI UI]", "EditResult:", (data.edits || []).length, "edits");
         if (data.edits && data.edits.length > 0) {
             data.edits.forEach(function (edit) {
                 _appendEditCard(edit);
@@ -438,11 +467,17 @@ define(function (require, exports, module) {
     }
 
     function _onError(_event, data) {
+        console.log("[AI UI]", "Error:", (data.error || "").slice(0, 200));
         _appendErrorMessage(data.error);
         // Don't stop streaming — the node side may continue (partial results)
     }
 
     function _onComplete(_event, data) {
+        console.log("[AI UI]", "Complete. textChunks=" + _traceTextChunks,
+            "toolStreams=" + JSON.stringify(_traceToolStreamCounts));
+        // Reset trace counters for next query
+        _traceTextChunks = 0;
+        _traceToolStreamCounts = {};
         _setStreaming(false);
     }
 
@@ -654,10 +689,17 @@ define(function (require, exports, module) {
 
     /**
      * Mark all active (non-done) tool indicators as finished.
+     * Tools that already received _updateToolIndicator (spinner replaced with
+     * .ai-tool-icon) are skipped — their delayed timeout will add .ai-tool-done.
+     * This only force-finishes tools that never got a toolInfo (e.g. interrupted).
      */
     function _finishActiveTools() {
         $messages.find(".ai-msg-tool:not(.ai-tool-done)").each(function () {
             const $prev = $(this);
+            // _updateToolIndicator already ran — let the delayed timeout handle it
+            if ($prev.find(".ai-tool-icon").length) {
+                return;
+            }
             $prev.addClass("ai-tool-done");
             const iconClass = $prev.attr("data-tool-icon") || "fa-solid fa-check";
             const color = $prev.css("--tool-color") || "#adb9bd";
