Agent Debug logging: detect mode changes, fix tools timing, add tool… (#4929)

* Title: Debug logging: detect mode changes, fix tools timing, add toolsFile to llm_request * feedback updates
2026-05-31 00:10:04 +08:00 · 2026-04-02 00:45:47 -07:00
parent 8a8016c7d7
commit d85e24d3d0
5 changed files with 103 additions and 48 deletions
--- a/extensions/copilot/assets/prompts/skills/troubleshoot/SKILL.md
+++ b/extensions/copilot/assets/prompts/skills/troubleshoot/SKILL.md
@@ -66,7 +66,7 @@ Key attrs: `args` (JSON string of tool input), `result` (tool output or error te
 ```jsonl
 {"ts":1773200231010,"dur":3001,"sid":"62f52dec","type":"llm_request","name":"chat:gpt-4o","spanId":"000000000000000c","parentSpanId":"0000000000000003","status":"ok","attrs":{"model":"gpt-4o","inputTokens":15025,"outputTokens":126,"ttft":1987,"maxTokens":32000,"systemPromptFile":"system_prompt_0.json","userRequest":"echo hello","inputMessages":"[{...}]"}}
 ```
-Key attrs: `model`, `inputTokens`, `outputTokens`, `ttft` (time to first token in ms), `maxTokens`, `temperature`, `topP`, `systemPromptFile` (references a file in the session directory), `userRequest` (the full user message content, untruncated), `inputMessages` (full messages array as JSON, pre-truncated at 64KB), `error` (when failed).
+Key attrs: `model`, `inputTokens`, `outputTokens`, `ttft` (time to first token in ms), `maxTokens`, `temperature`, `topP`, `systemPromptFile` (references a system prompt file in the session directory), `toolsFile` (references a tools file in the session directory), `userRequest` (the full user message content, untruncated), `inputMessages` (full messages array as JSON, pre-truncated at 64KB), `error` (when failed).

 #### agent_response — model output (text + tool calls)
 ```jsonl
--- a/extensions/copilot/src/extension/chat/vscode-node/chatDebugFileLoggerService.ts
+++ b/extensions/copilot/src/extension/chat/vscode-node/chatDebugFileLoggerService.ts
@@ -47,14 +47,14 @@ interface IActiveLogSession {
 	hasOwnSpans: boolean;
 	/** Whether models.json has already been written to this session's directory */
 	modelSnapshotWritten: boolean;
-	/** Model name of the last-written system prompt (undefined = none written yet) */
-	systemPromptModel: string | undefined;
+	/** Key identifying the last-written system prompt: model + agent/mode name (undefined = none written yet) */
+	systemPromptKey: string | undefined;
 	/** Index of the next system_prompt file to write */
 	systemPromptIndex: number;
 	/** File name of the most recently written system prompt (e.g., 'system_prompt_0.json') */
 	currentSystemPromptFile: string | undefined;
-	/** Model name of the last-written tools file (undefined = none written yet) */
-	toolsModel: string | undefined;
+	/** Key identifying the last-written tools file: model + agent/mode name (undefined = none written yet) */
+	toolsKey: string | undefined;
 	/** Index of the next tools file to write */
 	toolsIndex: number;
 	/** File name of the most recently written tools file (e.g., 'tools_0.json') */
@@ -285,10 +285,10 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
 			label: childInfo?.label,
 			hasOwnSpans,
 			modelSnapshotWritten: false,
-			systemPromptModel: undefined,
+			systemPromptKey: undefined,
 			systemPromptIndex: 0,
 			currentSystemPromptFile: undefined,
-			toolsModel: undefined,
+			toolsKey: undefined,
 			toolsIndex: 0,
 			currentToolsFile: undefined,
 		};
@@ -520,18 +520,19 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
 		//      (handled in _ensureSession's child branch).
 		this._ensureSession(sessionId);

-		// Write system_prompt JSON when model changes (before buffering so llm_request gets the file ref)
+		// Write system_prompt JSON when model or mode changes (before buffering so llm_request gets the file ref)
 		if (opName === GenAiOperationName.CHAT) {
 			const session = this._activeSessions.get(sessionId);
 			if (session && session.hasOwnSpans && !session.parentSessionId) {
 				const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
 					?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
 					?? 'unknown';
-				if (model !== session.systemPromptModel) {
-					const systemInstructions = asString(span.attributes[GenAiAttr.SYSTEM_INSTRUCTIONS]);
-					if (systemInstructions) {
+				const systemInstructions = asString(span.attributes[GenAiAttr.SYSTEM_INSTRUCTIONS]);
+				if (systemInstructions) {
+					const key = `${model}:${systemInstructions.length}`;
+					if (key !== session.systemPromptKey) {
 						const fileName = `system_prompt_${session.systemPromptIndex}.json`;
-						session.systemPromptModel = model;
+						session.systemPromptKey = key;
 						session.systemPromptIndex++;
 						session.currentSystemPromptFile = fileName;
 						this._enqueueFileWrite(session, systemInstructions, fileName);
@@ -550,43 +551,16 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
 			}
 		}

-		// Write tools JSON when model changes on INVOKE_AGENT spans (tool definitions live on agent span)
-		if (opName === GenAiOperationName.INVOKE_AGENT && !span.parentSpanId) {
-			const session = this._activeSessions.get(sessionId);
-			if (session && session.hasOwnSpans && !session.parentSessionId) {
-				const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
-					?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
-					?? 'unknown';
-				if (model !== session.toolsModel) {
-					const toolDefs = asString(span.attributes[GenAiAttr.TOOL_DEFINITIONS]);
-					if (toolDefs) {
-						const fileName = `tools_${session.toolsIndex}.json`;
-						session.toolsModel = model;
-						session.toolsIndex++;
-						session.currentToolsFile = fileName;
-						this._enqueueFileWrite(session, toolDefs, fileName);
-						this._bufferEntry(sessionId, {
-							ts: span.startTime,
-							dur: 0,
-							sid: sessionId,
-							type: 'generic',
-							name: 'tools_ref',
-							spanId: `tools-${span.spanId}`,
-							status: 'ok',
-							attrs: { file: fileName, model },
-						});
-					}
-				}
-			}
-		}
-
 		if (entry) {
-			// Attach current system prompt file reference to llm_request entries
+			// Attach current system prompt and tools file references to llm_request entries
 			if (entry.type === 'llm_request') {
 				const session = this._activeSessions.get(sessionId);
 				if (session?.currentSystemPromptFile) {
 					entry.attrs.systemPromptFile = session.currentSystemPromptFile;
 				}
+				if (session?.currentToolsFile) {
+					entry.attrs.toolsFile = session.currentToolsFile;
+				}
 			}
 			this._bufferEntry(sessionId, entry);
 		}
@@ -624,6 +598,11 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
 			return;
 		}

+		if (event.eventName === 'tools_available') {
+			this._onToolsAvailableEvent(event);
+			return;
+		}
+
 		if (event.eventName !== 'user_message') {
 			return;
 		}
@@ -725,6 +704,49 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
 		});
 	}

+	private _onToolsAvailableEvent(event: ISpanEventData): void {
+		const sessionId = typeof event.attributes[CopilotChatAttr.CHAT_SESSION_ID] === 'string'
+			? event.attributes[CopilotChatAttr.CHAT_SESSION_ID] as string
+			: (event.parentSpanId ? this._spanSessionIndex.get(event.parentSpanId) : undefined);
+
+		if (!sessionId) {
+			return;
+		}
+
+		// Ensure session exists — tools_available fires early, before any span completes
+		this._ensureSession(sessionId);
+
+		const session = this._activeSessions.get(sessionId);
+		if (!session || session.parentSessionId) {
+			return;
+		}
+
+		const toolDefs = typeof event.attributes.toolDefinitions === 'string' ? event.attributes.toolDefinitions : undefined;
+		if (!toolDefs) {
+			return;
+		}
+
+		// Use the current systemPromptKey to detect model/mode — tools change when the prompt changes
+		const key = session.systemPromptKey ?? 'unknown';
+		if (key !== session.toolsKey) {
+			const fileName = `tools_${session.toolsIndex}.json`;
+			session.toolsKey = key;
+			session.toolsIndex++;
+			session.currentToolsFile = fileName;
+			this._enqueueFileWrite(session, toolDefs, fileName);
+			this._bufferEntry(sessionId, {
+				ts: event.timestamp,
+				dur: 0,
+				sid: sessionId,
+				type: 'generic',
+				name: 'tools_ref',
+				spanId: `tools-${event.spanId}`,
+				status: 'ok',
+				attrs: { file: fileName },
+			});
+		}
+	}
+
 	// ── Core debug event handling (discovery, skill loading, etc.) ──

 	private _onCoreDebugEvent(event: vscode.ChatDebugEvent): void {
--- a/extensions/copilot/src/extension/intents/node/toolCallingLoop.ts
+++ b/extensions/copilot/src/extension/intents/node/toolCallingLoop.ts
@@ -171,6 +171,9 @@ export abstract class ToolCallingLoop<TOptions extends IToolCallingLoopOptions =
 	private stopHookReason: string | undefined;
 	private additionalHookContext: string | undefined;
 	private stopHookUserInitiated = false;
+	private agentSpan: ISpanHandle | undefined;
+	private chatSessionIdForTools: string | undefined;
+	private toolsAvailableEmitted = false;

 	public appendAdditionalHookContext(context: string): void {
 		if (!context) {
@@ -700,6 +703,10 @@ export abstract class ToolCallingLoop<TOptions extends IToolCallingLoopOptions =
 			?? (this.options.request as { participant?: string }).participant
 			?? 'GitHub Copilot Chat';

+		// Extract custom mode name for debug logging (kept separate from agentName to avoid metric cardinality)
+		const modeInstructions = (this.options.request as { modeInstructions2?: { name?: string; isBuiltin?: boolean } }).modeInstructions2;
+		const customModeName = modeInstructions?.name && !modeInstructions.isBuiltin ? modeInstructions.name : undefined;
+
 		// If this is a subagent request, look up the parent trace context stored by the parent agent's execute_tool span
 		// Try subAgentInvocationId first (unique per subagent, supports parallel), then request-level key
 		const subAgentInvocationId = this.options.request.subAgentInvocationId;
@@ -729,6 +736,7 @@ export abstract class ToolCallingLoop<TOptions extends IToolCallingLoopOptions =
 					[GenAiAttr.CONVERSATION_ID]: this.options.conversation.sessionId,
 					[CopilotChatAttr.SESSION_ID]: this.options.conversation.sessionId,
 					...(chatSessionId ? { [CopilotChatAttr.CHAT_SESSION_ID]: chatSessionId } : {}),
+					...(customModeName ? { 'copilot_chat.mode_name': customModeName } : {}),
 					...workspaceMetadataToOTelAttributes(resolveWorkspaceOTelMetadata(this._gitService)),
 				},
 				parentTraceContext,
@@ -834,6 +842,11 @@ export abstract class ToolCallingLoop<TOptions extends IToolCallingLoopOptions =
 		let stopHookActive = false;
 		const sessionId = this.options.conversation.sessionId;

+		// Store span context so runOne() can emit tools_available on first call
+		this.agentSpan = agentSpan;
+		this.chatSessionIdForTools = chatSessionId;
+		this.toolsAvailableEmitted = false;
+
 		while (true) {
 			if (lastResult && i++ >= this.options.toolCallLimit) {
 				// In Autopilot mode, silently increase the limit and continue
@@ -1098,6 +1111,17 @@ export abstract class ToolCallingLoop<TOptions extends IToolCallingLoopOptions =
 	/** Runs a single iteration of the tool calling loop. */
 	public async runOne(outputStream: ChatResponseStream | undefined, iterationNumber: number, token: CancellationToken): Promise<IToolCallSingleResult> {
 		let availableTools = await this.getAvailableTools(outputStream, token);
+
+		// Emit tools_available on the agent span once, before the first CHAT span
+		// starts in fetch(). This lets the debug logger write tools_*.json early.
+		if (!this.toolsAvailableEmitted && this.agentSpan && availableTools.length > 0) {
+			this.toolsAvailableEmitted = true;
+			this.agentSpan.addEvent('tools_available', {
+				toolDefinitions: JSON.stringify(availableTools.map(t => ({ type: 'function', name: t.name, description: t.description }))),
+				...(this.chatSessionIdForTools ? { [CopilotChatAttr.CHAT_SESSION_ID]: this.chatSessionIdForTools } : {}),
+			});
+		}
+
 		const context = this.createPromptContext(availableTools, outputStream);
 		const isContinuation = context.isContinuation || false;
 		markChatExt(this.options.conversation.sessionId, ChatExtPerfMark.WillBuildPrompt);
--- a/extensions/copilot/src/extension/prompt/node/chatMLFetcher.ts
+++ b/extensions/copilot/src/extension/prompt/node/chatMLFetcher.ts
@@ -262,9 +262,18 @@ export class ChatMLFetcherImpl extends AbstractChatMLFetcher {
 						?? (requestBody as Record<string, unknown>).system
 						?? (requestBody as Record<string, unknown>).instructions;
 					if (systemContent) {
-						const systemText = typeof systemContent === 'string'
-							? systemContent
-							: JSON.stringify(systemContent);
+						let systemText: string;
+						if (typeof systemContent === 'string') {
+							systemText = systemContent;
+						} else if (Array.isArray(systemContent)) {
+							// Anthropic format: array of content blocks — extract text only,
+							// dropping metadata like cache_control so the value is stable across turns.
+							systemText = (systemContent as Array<{ text?: string }>)
+								.map(b => b.text ?? '')
+								.join('\n');
+						} else {
+							systemText = JSON.stringify(systemContent);
+						}
 						otelInferenceSpan.setAttribute(GenAiAttr.SYSTEM_INSTRUCTIONS, systemText);
 					}
 				}
--- a/extensions/copilot/src/extension/trajectory/vscode-node/otelSpanToChatDebugEvent.ts
+++ b/extensions/copilot/src/extension/trajectory/vscode-node/otelSpanToChatDebugEvent.ts
@@ -423,7 +423,7 @@ function spanToHookExecutionEvent(span: ICompletedSpanData): vscode.ChatDebugGen
 	evt.parentEventId = span.parentSpanId;
 	const prefix = hookCommand ? `${hookCommand} ` : '';
 	evt.details = `${prefix}(${durationMs}ms, ${resultKind ?? 'unknown'})`;
-	evt.category = 'hook';
+	evt.category = 'discovery';
 	return evt;
 }

@@ -440,7 +440,7 @@ function spanToSdkHookEvent(span: ICompletedSpanData): vscode.ChatDebugGenericEv
 	evt.id = span.spanId;
 	evt.parentEventId = span.parentSpanId;
 	evt.details = `${span.name} (${durationMs}ms, ${isError ? 'error' : 'success'})`;
-	evt.category = 'hook';
+	evt.category = 'discovery';
 	return evt;
 }