Skip to content

Commit 1275fec

Browse files
vijayupadyavijayupadya
authored
Troubleshooting: Enrich chat debug JSONL logs (#4887)
* Enrich chat debug JSONL logs * feedback update * Feedback update2
1 parent 26fc626 commit 1275fec

5 files changed

Lines changed: 280 additions & 44 deletions

File tree

‎assets/prompts/skills/troubleshoot/SKILL.md‎

Lines changed: 27 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,10 @@ Use direct debug log files written by Copilot Chat:
2828
debug-logs/<sessionId>/
2929
main.jsonl — always start here; primary conversation log
3030
models.json — (optional) snapshot of available models at session start
31+
system_prompt_0.json — (optional) full system prompt sent to the model (untruncated)
32+
system_prompt_1.json — (optional) written when the model changes mid-session
33+
tools_0.json — (optional) tool definitions sent to the model
34+
tools_1.json — (optional) written when the model changes mid-session
3135
runSubagent-<agentName>-<uuid>.jsonl — (optional) subagent's tool calls & LLM requests
3236
searchSubagent-<uuid>.jsonl — (optional) search subagent work
3337
title-<uuid>.jsonl — (optional, UI-only) title generation
@@ -37,6 +41,8 @@ debug-logs/<sessionId>/
3741

3842
Always read `main.jsonl` first — it has the full conversation flow. Child files only appear when those operations occurred. `main.jsonl` contains `child_session_ref` entries that link to each child file by name. Title, categorization, and summarize files are UI housekeeping and rarely relevant to troubleshooting. When investigating model availability or selection issues, read `models.json` — it contains the full list of models (with capabilities, billing, and limits) that were available when the session started.
3943

44+
When investigating what the model was told (system prompt, instructions), read the `system_prompt_*.json` file referenced by a `system_prompt_ref` entry in `main.jsonl`. The file contains the full untruncated system prompt as `{ "content": "..." }`. When investigating which tools were available, read the `tools_*.json` file similarly. If the model changed mid-session, multiple numbered files exist — each `llm_request` entry has a `systemPromptFile` attr indicating which file was active for that request.
45+
4046
Each line is a JSON object. Common fields: `ts` (epoch ms), `dur` (duration ms), `sid` (session ID), `type`, `name`, `spanId`, `parentSpanId`, `status` (`ok`|`error`), `attrs` (type-specific details).
4147

4248
### Event Type Reference with Examples
@@ -58,15 +64,15 @@ Key attrs: `args` (JSON string of tool input), `result` (tool output or error te
5864

5965
#### llm_request — model round-trip
6066
```jsonl
61-
{"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}}
67+
{"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":"[{...}]"}}
6268
```
63-
Key attrs: `model`, `inputTokens`, `outputTokens`, `ttft` (time to first token in ms), `error` (when failed).
69+
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).
6470

6571
#### agent_response — model output (text + tool calls)
6672
```jsonl
67-
{"ts":1773200234011,"dur":0,"sid":"62f52dec","type":"agent_response","name":"agent_response","spanId":"agent-msg-000000000000000c","parentSpanId":"0000000000000003","status":"ok","attrs":{"response":"[{\"role\":\"assistant\",\"parts\":[{\"type\":\"text\",\"content\":\"Running your command now.\"},{\"type\":\"tool_call\",\"name\":\"run_in_terminal\",\"arguments\":\"{...}\"}]}]"}}
73+
{"ts":1773200234011,"dur":0,"sid":"62f52dec","type":"agent_response","name":"agent_response","spanId":"agent-msg-000000000000000c","parentSpanId":"0000000000000003","status":"ok","attrs":{"response":"[{\"role\":\"assistant\",...}]","reasoning":"The user wants me to run a command."}}
6874
```
69-
Key attrs: `response` (JSON-encoded array of message parts; may be truncated).
75+
Key attrs: `response` (JSON-encoded array of message parts; may be truncated), `reasoning` (optional — the model's chain-of-thought/thinking text when thinking mode is active; may be truncated).
7076

7177
#### user_message — user input
7278
```jsonl
@@ -85,6 +91,23 @@ Key attrs: `agentName`, `description` (optional), `error` (when failed).
8591
{"ts":1773200260000,"dur":0,"sid":"62f52dec","type":"generic","name":"some-event","spanId":"abc123","status":"ok","attrs":{"details":"Additional context","category":"some-category"}}
8692
```
8793

94+
Special generic entries:
95+
- `system_prompt_ref` — references a `system_prompt_*.json` file in the session directory. `attrs.file` is the filename, `attrs.model` is the model it was written for. Read this file to see the full system prompt.
96+
- `tools_ref` — references a `tools_*.json` file. `attrs.file` is the filename, `attrs.model` is the model.
97+
98+
#### session_start — session metadata (appears once at session start)
99+
```jsonl
100+
{"ts":1773200251300,"dur":0,"sid":"62f52dec","type":"session_start","name":"session_start","spanId":"session-start-62f52dec","status":"ok","attrs":{"copilotVersion":"0.43.2026033104","vscodeVersion":"1.99.0"}}
101+
```
102+
Key attrs: `copilotVersion`, `vscodeVersion`. Useful for identifying which build produced the logs.
103+
104+
#### turn_start / turn_end — tool-calling loop iteration boundaries
105+
```jsonl
106+
{"ts":1773200251400,"dur":0,"sid":"62f52dec","type":"turn_start","name":"turn_start:0","spanId":"turn-start-X-0","status":"ok","attrs":{"turnId":"0"}}
107+
{"ts":1773200255000,"dur":0,"sid":"62f52dec","type":"turn_end","name":"turn_end:0","spanId":"turn-end-X-0","status":"ok","attrs":{"turnId":"0"}}
108+
```
109+
Key attrs: `turnId` (iteration number within a single user request's tool-calling loop). Use these to identify which iteration events belong to and to count total loop iterations.
110+
88111
### Reading the event hierarchy
89112

90113
Events form a tree via `spanId`/`parentSpanId`. A typical chain:

‎src/extension/chat/vscode-node/chatDebugFileLoggerService.ts‎

Lines changed: 188 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import * as fs from 'fs';
77
import * as vscode from 'vscode';
88
import { IChatDebugFileLoggerService, sessionResourceToId } from '../../../platform/chat/common/chatDebugFileLoggerService';
99
import { ConfigKey, IConfigurationService } from '../../../platform/configuration/common/configurationService';
10+
import { IEnvService } from '../../../platform/env/common/envService';
1011
import { IVSCodeExtensionContext } from '../../../platform/extContext/common/extensionContext';
1112
import { createDirectoryIfNotExists, IFileSystemService } from '../../../platform/filesystem/common/fileSystemService';
1213
import { ILogService } from '../../../platform/log/common/logService';
@@ -46,6 +47,18 @@ interface IActiveLogSession {
4647
hasOwnSpans: boolean;
4748
/** Whether models.json has already been written to this session's directory */
4849
modelSnapshotWritten: boolean;
50+
/** Model name of the last-written system prompt (undefined = none written yet) */
51+
systemPromptModel: string | undefined;
52+
/** Index of the next system_prompt file to write */
53+
systemPromptIndex: number;
54+
/** File name of the most recently written system prompt (e.g., 'system_prompt_0.json') */
55+
currentSystemPromptFile: string | undefined;
56+
/** Model name of the last-written tools file (undefined = none written yet) */
57+
toolsModel: string | undefined;
58+
/** Index of the next tools file to write */
59+
toolsIndex: number;
60+
/** File name of the most recently written tools file (e.g., 'tools_0.json') */
61+
currentToolsFile: string | undefined;
4962
}
5063

5164
/**
@@ -59,7 +72,7 @@ interface IDebugLogEntry {
5972
/** Chat session ID */
6073
readonly sid: string;
6174
/** Event type */
62-
readonly type: 'tool_call' | 'llm_request' | 'user_message' | 'agent_response' | 'subagent' | 'discovery' | 'error' | 'generic' | 'child_session_ref' | 'hook';
75+
readonly type: 'session_start' | 'tool_call' | 'llm_request' | 'user_message' | 'agent_response' | 'subagent' | 'discovery' | 'error' | 'generic' | 'child_session_ref' | 'hook' | 'turn_start' | 'turn_end';
6376
/** Descriptive name */
6477
readonly name: string;
6578
/** Span or event ID */
@@ -99,6 +112,7 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
99112
@IConfigurationService private readonly _configurationService: IConfigurationService,
100113
@IExperimentationService private readonly _experimentationService: IExperimentationService,
101114
@ITelemetryService private readonly _telemetryService: ITelemetryService,
115+
@IEnvService private readonly _envService: IEnvService,
102116
) {
103117
super();
104118

@@ -211,12 +225,7 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
211225
existing.hasOwnSpans = true;
212226
// Now that we know this is a real session, replay pending core events
213227
if (!existing.parentSessionId) {
214-
for (const entry of this._pendingCoreEvents) {
215-
this._bufferEntry(sessionId, { ...entry, sid: sessionId });
216-
}
217-
if (this._modelSnapshot) {
218-
this._enqueueModelSnapshotWrite(existing);
219-
}
228+
this._emitSessionStartAndReplay(sessionId, existing);
220229
}
221230
}
222231
return;
@@ -276,20 +285,19 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
276285
label: childInfo?.label,
277286
hasOwnSpans,
278287
modelSnapshotWritten: false,
288+
systemPromptModel: undefined,
289+
systemPromptIndex: 0,
290+
currentSystemPromptFile: undefined,
291+
toolsModel: undefined,
292+
toolsIndex: 0,
293+
currentToolsFile: undefined,
279294
};
280295
this._activeSessions.set(sessionId, session);
281296

282297
// Replay pending core events only for parent sessions that have their own spans
283298
// (not for sessions auto-created as a side effect of child parent references)
284299
if (!childInfo && hasOwnSpans) {
285-
for (const entry of this._pendingCoreEvents) {
286-
this._bufferEntry(sessionId, { ...entry, sid: sessionId });
287-
}
288-
289-
// Write cached model snapshot as models.json in the session directory
290-
if (this._modelSnapshot) {
291-
this._enqueueModelSnapshotWrite(session);
292-
}
300+
this._emitSessionStartAndReplay(sessionId, session);
293301
}
294302

295303
// Start auto-flush timer if this is the first active session
@@ -424,6 +432,52 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
424432
}
425433
}
426434

435+
private _enqueueFileWrite(session: IActiveLogSession, content: string, fileName: string): void {
436+
session.flushPromise = session.flushPromise.then(
437+
() => this._writeSessionFile(session, content, fileName),
438+
() => this._writeSessionFile(session, content, fileName),
439+
);
440+
}
441+
442+
private async _writeSessionFile(session: IActiveLogSession, content: string, fileName: string): Promise<void> {
443+
try {
444+
if (!session.dirEnsured) {
445+
await createDirectoryIfNotExists(this._fileSystemService, session.sessionDir);
446+
session.dirEnsured = true;
447+
}
448+
const fileUri = URI.joinPath(session.sessionDir, fileName);
449+
await fs.promises.writeFile(fileUri.fsPath, fileName.endsWith('.json') ? JSON.stringify({ content }, null, 2) : content, 'utf-8');
450+
} catch (err) {
451+
this._logService.error(`[ChatDebugFileLogger] Failed to write ${fileName}`, err);
452+
}
453+
}
454+
455+
/**
456+
* Emit a session_start entry, replay cached core events, and write the model snapshot.
457+
* Called when a parent session is first promoted to hasOwnSpans.
458+
*/
459+
private _emitSessionStartAndReplay(sessionId: string, session: IActiveLogSession): void {
460+
this._bufferEntry(sessionId, {
461+
ts: Date.now(),
462+
dur: 0,
463+
sid: sessionId,
464+
type: 'session_start',
465+
name: 'session_start',
466+
spanId: `session-start-${sessionId}`,
467+
status: 'ok',
468+
attrs: {
469+
copilotVersion: this._envService.getVersion(),
470+
vscodeVersion: this._envService.vscodeVersion,
471+
},
472+
});
473+
for (const entry of this._pendingCoreEvents) {
474+
this._bufferEntry(sessionId, { ...entry, sid: sessionId });
475+
}
476+
if (this._modelSnapshot) {
477+
this._enqueueModelSnapshotWrite(session);
478+
}
479+
}
480+
427481
// ── OTel span handling ──
428482

429483
private _onSpanCompleted(span: ICompletedSpanData): void {
@@ -466,7 +520,74 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
466520
// (handled in _ensureSession's child branch).
467521
this._ensureSession(sessionId);
468522

523+
// Write system_prompt JSON when model changes (before buffering so llm_request gets the file ref)
524+
if (opName === GenAiOperationName.CHAT) {
525+
const session = this._activeSessions.get(sessionId);
526+
if (session && session.hasOwnSpans && !session.parentSessionId) {
527+
const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
528+
?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
529+
?? 'unknown';
530+
if (model !== session.systemPromptModel) {
531+
const systemInstructions = asString(span.attributes[GenAiAttr.SYSTEM_INSTRUCTIONS]);
532+
if (systemInstructions) {
533+
const fileName = `system_prompt_${session.systemPromptIndex}.json`;
534+
session.systemPromptModel = model;
535+
session.systemPromptIndex++;
536+
session.currentSystemPromptFile = fileName;
537+
this._enqueueFileWrite(session, systemInstructions, fileName);
538+
this._bufferEntry(sessionId, {
539+
ts: span.startTime,
540+
dur: 0,
541+
sid: sessionId,
542+
type: 'generic',
543+
name: 'system_prompt_ref',
544+
spanId: `sys-prompt-${span.spanId}`,
545+
status: 'ok',
546+
attrs: { file: fileName, model },
547+
});
548+
}
549+
}
550+
}
551+
}
552+
553+
// Write tools JSON when model changes on INVOKE_AGENT spans (tool definitions live on agent span)
554+
if (opName === GenAiOperationName.INVOKE_AGENT && !span.parentSpanId) {
555+
const session = this._activeSessions.get(sessionId);
556+
if (session && session.hasOwnSpans && !session.parentSessionId) {
557+
const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
558+
?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
559+
?? 'unknown';
560+
if (model !== session.toolsModel) {
561+
const toolDefs = asString(span.attributes[GenAiAttr.TOOL_DEFINITIONS]);
562+
if (toolDefs) {
563+
const fileName = `tools_${session.toolsIndex}.json`;
564+
session.toolsModel = model;
565+
session.toolsIndex++;
566+
session.currentToolsFile = fileName;
567+
this._enqueueFileWrite(session, toolDefs, fileName);
568+
this._bufferEntry(sessionId, {
569+
ts: span.startTime,
570+
dur: 0,
571+
sid: sessionId,
572+
type: 'generic',
573+
name: 'tools_ref',
574+
spanId: `tools-${span.spanId}`,
575+
status: 'ok',
576+
attrs: { file: fileName, model },
577+
});
578+
}
579+
}
580+
}
581+
}
582+
469583
if (entry) {
584+
// Attach current system prompt file reference to llm_request entries
585+
if (entry.type === 'llm_request') {
586+
const session = this._activeSessions.get(sessionId);
587+
if (session?.currentSystemPromptFile) {
588+
entry.attrs.systemPromptFile = session.currentSystemPromptFile;
589+
}
590+
}
470591
this._bufferEntry(sessionId, entry);
471592
}
472593

@@ -478,6 +599,7 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
478599
if (opName === GenAiOperationName.CHAT) {
479600
// Extract agent response summary from output messages
480601
if (outputMessages) {
602+
const reasoningContent = asString(span.attributes[CopilotChatAttr.REASONING_CONTENT]);
481603
this._bufferEntry(sessionId, {
482604
ts: span.endTime,
483605
dur: 0,
@@ -489,13 +611,19 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
489611
status: 'ok',
490612
attrs: {
491613
response: truncate(outputMessages, MAX_ATTR_VALUE_LENGTH),
614+
...(reasoningContent ? { reasoning: truncate(reasoningContent, MAX_ATTR_VALUE_LENGTH) } : {}),
492615
},
493616
});
494617
}
495618
}
496619
}
497620

498621
private _onSpanEvent(event: ISpanEventData): void {
622+
if (event.eventName === 'turn_start' || event.eventName === 'turn_end') {
623+
this._onTurnBoundaryEvent(event);
624+
return;
625+
}
626+
499627
if (event.eventName !== 'user_message') {
500628
return;
501629
}
@@ -506,7 +634,9 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
506634

507635
// If the event carries a session ID, route to that specific session
508636
const eventSessionId = event.attributes[CopilotChatAttr.CHAT_SESSION_ID];
509-
if (typeof eventSessionId === 'string' && this._activeSessions.has(eventSessionId)) {
637+
if (typeof eventSessionId === 'string') {
638+
// Ensure the session buffer exists so early events (before any span completes) are captured
639+
this._ensureSession(eventSessionId);
510640
this._bufferEntry(eventSessionId, {
511641
ts: event.timestamp,
512642
dur: 0,
@@ -568,6 +698,33 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
568698
}
569699
}
570700

701+
private _onTurnBoundaryEvent(event: ISpanEventData): void {
702+
const type = event.eventName === 'turn_start' ? 'turn_start' : 'turn_end';
703+
const turnId = typeof event.attributes.turnId === 'string' ? event.attributes.turnId : String(event.attributes.turnId ?? '');
704+
const sessionId = typeof event.attributes[CopilotChatAttr.CHAT_SESSION_ID] === 'string'
705+
? event.attributes[CopilotChatAttr.CHAT_SESSION_ID] as string
706+
: (event.parentSpanId ? this._spanSessionIndex.get(event.parentSpanId) : undefined);
707+
708+
if (!sessionId) {
709+
return;
710+
}
711+
712+
// Ensure the session buffer exists so early turn events are captured
713+
this._ensureSession(sessionId);
714+
715+
this._bufferEntry(sessionId, {
716+
ts: event.timestamp,
717+
dur: 0,
718+
sid: sessionId,
719+
type,
720+
name: `${type}:${turnId}`,
721+
spanId: `${type}-${event.spanId}-${turnId}`,
722+
parentSpanId: event.parentSpanId,
723+
status: 'ok',
724+
attrs: { turnId },
725+
});
726+
}
727+
571728
// ── Core debug event handling (discovery, skill loading, etc.) ──
572729

573730
private _onCoreDebugEvent(event: vscode.ChatDebugEvent): void {
@@ -666,6 +823,21 @@ export class ChatDebugFileLoggerService extends Disposable implements IChatDebug
666823
...(span.attributes[CopilotChatAttr.TIME_TO_FIRST_TOKEN] !== undefined
667824
? { ttft: asNumber(span.attributes[CopilotChatAttr.TIME_TO_FIRST_TOKEN]) }
668825
: {}),
826+
...(span.attributes[CopilotChatAttr.USER_REQUEST] !== undefined
827+
? { userRequest: String(span.attributes[CopilotChatAttr.USER_REQUEST]) }
828+
: {}),
829+
...(span.attributes[GenAiAttr.INPUT_MESSAGES] !== undefined
830+
? { inputMessages: String(span.attributes[GenAiAttr.INPUT_MESSAGES]) }
831+
: {}),
832+
...(span.attributes[GenAiAttr.REQUEST_MAX_TOKENS] !== undefined
833+
? { maxTokens: asNumber(span.attributes[GenAiAttr.REQUEST_MAX_TOKENS]) }
834+
: {}),
835+
...(span.attributes[GenAiAttr.REQUEST_TEMPERATURE] !== undefined
836+
? { temperature: asNumber(span.attributes[GenAiAttr.REQUEST_TEMPERATURE]) }
837+
: {}),
838+
...(span.attributes[GenAiAttr.REQUEST_TOP_P] !== undefined
839+
? { topP: asNumber(span.attributes[GenAiAttr.REQUEST_TOP_P]) }
840+
: {}),
669841
...(isError && span.status.message ? { error: span.status.message } : {}),
670842
},
671843
};

0 commit comments

Comments
 (0)