Book a Demo!
CoCalc Logo Icon
StoreFeaturesDocsShareSupportNewsAboutPoliciesSign UpSign In
microsoft
GitHub Repository: microsoft/vscode
Path: blob/main/extensions/copilot/src/extension/chat/vscode-node/chatDebugFileLoggerService.ts
13399 views
1
/*---------------------------------------------------------------------------------------------
2
* Copyright (c) Microsoft Corporation. All rights reserved.
3
* Licensed under the MIT License. See License.txt in the project root for license information.
4
*--------------------------------------------------------------------------------------------*/
5
6
import * as fs from 'fs';
7
import * as vscode from 'vscode';
8
import { IChatDebugFileLoggerService, IDebugLogEntry, sessionResourceToId } from '../../../platform/chat/common/chatDebugFileLoggerService';
9
import { ConfigKey, IConfigurationService } from '../../../platform/configuration/common/configurationService';
10
import { IEnvService } from '../../../platform/env/common/envService';
11
import { IVSCodeExtensionContext } from '../../../platform/extContext/common/extensionContext';
12
import { createDirectoryIfNotExists, IFileSystemService } from '../../../platform/filesystem/common/fileSystemService';
13
import { ILogService } from '../../../platform/log/common/logService';
14
import { CopilotChatAttr, GenAiAttr, GenAiOperationName } from '../../../platform/otel/common/index';
15
import { ICompletedSpanData, IOTelService, ISpanEventData, SpanStatusCode } from '../../../platform/otel/common/otelService';
16
import { IExperimentationService } from '../../../platform/telemetry/common/nullExperimentationService';
17
import { ITelemetryService } from '../../../platform/telemetry/common/telemetry';
18
import { Emitter } from '../../../util/vs/base/common/event';
19
import { Disposable } from '../../../util/vs/base/common/lifecycle';
20
import { extUriBiasedIgnorePathCase } from '../../../util/vs/base/common/resources';
21
import { URI } from '../../../util/vs/base/common/uri';
22
import { IExtensionContribution } from '../../common/contributions';
23
24
const DEBUG_LOGS_DIR_NAME = 'debug-logs';
25
const DEFAULT_MAX_RETAINED_LOGS = 50;
26
const DEFAULT_FLUSH_INTERVAL_MS = 4_000;
27
const MIN_FLUSH_INTERVAL_MS = 2_000;
28
const MAX_ATTR_VALUE_LENGTH = 5_000;
29
const MAX_PENDING_CORE_EVENTS = 100;
30
const DEFAULT_MAX_SESSION_LOG_MB = 100;
31
const TRUNCATION_RETAIN_RATIO = 0.6; // retain 60% of max on truncation
32
const MAX_SPAN_SESSION_INDEX = 10_000;
33
34
35
interface IActiveLogSession {
36
readonly uri: URI;
37
/** The directory containing this session's log files */
38
readonly sessionDir: URI;
39
readonly buffer: string[];
40
flushPromise: Promise<void>;
41
dirEnsured: boolean;
42
bytesWritten: number;
43
/** Parent session ID if this is a child session (e.g., title, categorization) */
44
readonly parentSessionId?: string;
45
/** Label for child sessions (e.g., 'title', 'categorization') */
46
readonly label?: string;
47
/** Whether this session has received its own OTel spans (vs being auto-created as a parent ref) */
48
hasOwnSpans: boolean;
49
/** Whether models.json has already been written to this session's directory */
50
modelSnapshotWritten: boolean;
51
/** Key identifying the last-written system prompt: model + agent/mode name (undefined = none written yet) */
52
systemPromptKey: string | undefined;
53
/** Index of the next system_prompt file to write */
54
systemPromptIndex: number;
55
/** File name of the most recently written system prompt (e.g., 'system_prompt_0.json') */
56
currentSystemPromptFile: string | undefined;
57
/** Key identifying the last-written tools file: model + agent/mode name (undefined = none written yet) */
58
toolsKey: string | undefined;
59
/** Index of the next tools file to write */
60
toolsIndex: number;
61
/** File name of the most recently written tools file (e.g., 'tools_0.json') */
62
currentToolsFile: string | undefined;
63
/** Pending tool definitions received before the session was promoted to hasOwnSpans */
64
pendingToolDefs: string | undefined;
65
/** Whether we've already checked disk for a previous session directory (prevents repeated sync FS calls) */
66
resumeChecked: boolean;
67
/** Run index: 0 for the first run, incremented on each VS Code restart that resumes this session */
68
runIndex: number;
69
}
70
71
// IDebugLogEntry is imported from and defined in the platform layer.
72
// Re-export for consumers that import from this file.
73
export type { IDebugLogEntry } from '../../../platform/chat/common/chatDebugFileLoggerService';
74
75
export class ChatDebugFileLoggerService extends Disposable implements IChatDebugFileLoggerService {
76
declare readonly _serviceBrand: undefined;
77
78
public readonly id = 'chatDebugFileLogger';
79
80
private readonly _onDidEmitEntry = this._register(new Emitter<{ sessionId: string; entry: IDebugLogEntry }>());
81
readonly onDidEmitEntry = this._onDidEmitEntry.event;
82
83
private readonly _activeSessions = new Map<string, IActiveLogSession>();
84
/** Maps child session ID → { parentSessionId, label } for child session routing */
85
private readonly _childSessionMap = new Map<string, { parentSessionId: string; label: string; parentToolSpanId?: string }>();
86
/** Maps spanId → resolved session ID for parent-span inheritance */
87
private readonly _spanSessionIndex = new Map<string, string>();
88
private readonly _pendingCoreEvents: IDebugLogEntry[] = [];
89
private _modelSnapshot: readonly unknown[] | undefined;
90
private _debugLogsDirUri: URI | undefined;
91
private _autoFlushTimer: ReturnType<typeof setInterval> | undefined;
92
private _autoFlushIntervalMs: number;
93
private _maxSessionLogBytes: number;
94
private _totalBytesWritten = 0;
95
private _totalSessionCount = 0;
96
97
constructor(
98
@IOTelService private readonly _otelService: IOTelService,
99
@IFileSystemService private readonly _fileSystemService: IFileSystemService,
100
@IVSCodeExtensionContext private readonly _extensionContext: IVSCodeExtensionContext,
101
@ILogService private readonly _logService: ILogService,
102
@IConfigurationService private readonly _configurationService: IConfigurationService,
103
@IExperimentationService private readonly _experimentationService: IExperimentationService,
104
@ITelemetryService private readonly _telemetryService: ITelemetryService,
105
@IEnvService private readonly _envService: IEnvService,
106
) {
107
super();
108
109
const enabled = this._configurationService.getExperimentBasedConfig(ConfigKey.Advanced.ChatDebugFileLogging, this._experimentationService);
110
if (!enabled) {
111
/* __GDPR__
112
"chatDebugFileLogger.disabled" : {
113
"owner": "vijayupadya",
114
"comment": "Chat debug file logging is disabled via experiment or config"
115
}
116
*/
117
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.disabled');
118
this._autoFlushIntervalMs = DEFAULT_FLUSH_INTERVAL_MS;
119
this._maxSessionLogBytes = DEFAULT_MAX_SESSION_LOG_MB * 1024 * 1024;
120
return;
121
}
122
123
this._autoFlushIntervalMs = Math.max(MIN_FLUSH_INTERVAL_MS, this._configurationService.getConfig(ConfigKey.Advanced.ChatDebugFileLoggingFlushInterval) ?? DEFAULT_FLUSH_INTERVAL_MS);
124
this._maxSessionLogBytes = this._resolveMaxSessionLogBytes();
125
126
// React to changes at runtime
127
this._register(this._configurationService.onDidChangeConfiguration(e => {
128
if (e.affectsConfiguration(ConfigKey.Advanced.ChatDebugFileLoggingFlushInterval.fullyQualifiedId)) {
129
this._autoFlushIntervalMs = Math.max(MIN_FLUSH_INTERVAL_MS, this._configurationService.getConfig(ConfigKey.Advanced.ChatDebugFileLoggingFlushInterval) ?? DEFAULT_FLUSH_INTERVAL_MS);
130
this._restartFlushTimer();
131
}
132
if (e.affectsConfiguration(ConfigKey.Advanced.ChatDebugFileLoggingMaxSessionLogSizeMB.fullyQualifiedId)) {
133
this._maxSessionLogBytes = this._resolveMaxSessionLogBytes();
134
}
135
}));
136
137
// Subscribe to OTel span completions
138
this._register(this._otelService.onDidCompleteSpan(span => {
139
this._onSpanCompleted(span);
140
}));
141
142
// Subscribe to OTel span events (real-time user messages)
143
this._register(this._otelService.onDidEmitSpanEvent(event => {
144
this._onSpanEvent(event);
145
}));
146
147
// Subscribe to core debug events (discovery, skill loading, etc.)
148
if (typeof vscode.chat?.onDidReceiveChatDebugEvent === 'function') {
149
this._register(vscode.chat.onDidReceiveChatDebugEvent(event => {
150
this._onCoreDebugEvent(event);
151
}));
152
}
153
}
154
155
private _resolveMaxSessionLogBytes(): number {
156
const raw = this._configurationService.getExperimentBasedConfig(ConfigKey.Advanced.ChatDebugFileLoggingMaxSessionLogSizeMB, this._experimentationService);
157
const mb = typeof raw === 'number' && Number.isFinite(raw) ? raw : DEFAULT_MAX_SESSION_LOG_MB;
158
return Math.max(1, Math.floor(mb)) * 1024 * 1024;
159
}
160
161
override dispose(): void {
162
if (this._autoFlushTimer) {
163
clearInterval(this._autoFlushTimer);
164
this._autoFlushTimer = undefined;
165
}
166
// Accumulate any remaining active session bytes before emitting telemetry
167
for (const session of this._activeSessions.values()) {
168
this._totalBytesWritten += session.bytesWritten;
169
}
170
/* __GDPR__
171
"chatDebugFileLogger.end" : {
172
"owner": "vijayupadya",
173
"comment": "Chat debug file logger is being disposed",
174
"totalBytesWritten": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "Total bytes written across all sessions" },
175
"sessionCount": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "Total number of sessions logged" }
176
}
177
*/
178
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.end', undefined, { totalBytesWritten: this._totalBytesWritten, sessionCount: this._totalSessionCount });
179
super.dispose();
180
}
181
182
public get debugLogsDir(): URI | undefined {
183
return this._getDebugLogsDir();
184
}
185
186
private _getDebugLogsDir(): URI | undefined {
187
if (this._debugLogsDirUri) {
188
return this._debugLogsDirUri;
189
}
190
const storageUri = this._extensionContext.storageUri as URI | undefined;
191
if (!storageUri) {
192
return undefined;
193
}
194
this._debugLogsDirUri = URI.joinPath(storageUri, DEBUG_LOGS_DIR_NAME);
195
return this._debugLogsDirUri;
196
}
197
198
async startSession(sessionId: string): Promise<void> {
199
this._ensureSession(sessionId, /* hasOwnSpans */ true);
200
}
201
202
startChildSession(childSessionId: string, parentSessionId: string, label: string, parentToolSpanId?: string): void {
203
if (!this._childSessionMap.has(childSessionId)) {
204
this._childSessionMap.set(childSessionId, { parentSessionId, label, parentToolSpanId });
205
}
206
}
207
208
registerSpanSession(spanId: string, sessionId: string): void {
209
this._spanSessionIndex.set(spanId, sessionId);
210
// Apply same eviction cap as _onSpanCompleted
211
if (this._spanSessionIndex.size > MAX_SPAN_SESSION_INDEX) {
212
const excess = this._spanSessionIndex.size - MAX_SPAN_SESSION_INDEX;
213
const iter = this._spanSessionIndex.keys();
214
for (let i = 0; i < excess; i++) {
215
this._spanSessionIndex.delete(iter.next().value!);
216
}
217
}
218
}
219
220
/**
221
* Synchronously ensure a session exists for buffering. Directory creation
222
* and old-log cleanup are deferred to the first flush.
223
*
224
* Sessions are organized in directories:
225
* - Parent session: `debug-logs/<sessionId>/main.jsonl`
226
* - Child session: `debug-logs/<parentSessionId>/<label>-<childSessionId>.jsonl`
227
*/
228
private _ensureSession(sessionId: string, hasOwnSpans = false): void {
229
const existing = this._activeSessions.get(sessionId);
230
if (existing) {
231
// Mark that this session now has its own spans (upgrades from auto-created parent ref)
232
if (hasOwnSpans && !existing.hasOwnSpans) {
233
existing.hasOwnSpans = true;
234
// Now that we know this is a real session, replay pending core events
235
if (!existing.parentSessionId) {
236
this._emitSessionStartAndReplay(sessionId, existing);
237
}
238
}
239
return;
240
}
241
242
this._totalSessionCount++;
243
244
const dir = this._getDebugLogsDir();
245
if (!dir) {
246
return;
247
}
248
249
const childInfo = this._childSessionMap.get(sessionId);
250
let sessionDir: URI;
251
let fileUri: URI;
252
253
if (childInfo) {
254
// Child session — write under parent's directory
255
sessionDir = URI.joinPath(dir, childInfo.parentSessionId);
256
const safeLabel = childInfo.label.replace(/[/\\:*?"<>|\x00-\x1f]/g, '_').replace(/\.\./g, '_');
257
const fileName = `${safeLabel}-${sessionId}.jsonl`;
258
fileUri = URI.joinPath(sessionDir, fileName);
259
260
// Ensure parent session exists so we can write a cross-reference.
261
// A child referencing a parent proves it is a main user session,
262
// so promote it with hasOwnSpans = true.
263
this._ensureSession(childInfo.parentSessionId, /* hasOwnSpans */ true);
264
265
// Write a cross-reference entry in the parent's main.jsonl
266
this._bufferEntry(childInfo.parentSessionId, {
267
ts: Date.now(),
268
dur: 0,
269
sid: childInfo.parentSessionId,
270
type: 'child_session_ref',
271
name: childInfo.label,
272
spanId: `child-ref-${sessionId}`,
273
...(childInfo.parentToolSpanId ? { parentSpanId: childInfo.parentToolSpanId } : {}),
274
status: 'ok',
275
attrs: {
276
childSessionId: sessionId,
277
childLogFile: `${safeLabel}-${sessionId}.jsonl`,
278
label: childInfo.label,
279
},
280
});
281
} else {
282
// Parent session — write as main.jsonl in its own directory
283
sessionDir = URI.joinPath(dir, sessionId);
284
fileUri = URI.joinPath(sessionDir, 'main.jsonl');
285
}
286
287
const session: IActiveLogSession = {
288
uri: fileUri,
289
sessionDir,
290
buffer: [],
291
flushPromise: Promise.resolve(),
292
dirEnsured: false,
293
bytesWritten: 0,
294
parentSessionId: childInfo?.parentSessionId,
295
label: childInfo?.label,
296
hasOwnSpans,
297
modelSnapshotWritten: false,
298
systemPromptKey: undefined,
299
systemPromptIndex: 0,
300
currentSystemPromptFile: undefined,
301
toolsKey: undefined,
302
toolsIndex: 0,
303
currentToolsFile: undefined,
304
pendingToolDefs: undefined,
305
resumeChecked: false,
306
runIndex: 0,
307
};
308
this._activeSessions.set(sessionId, session);
309
310
// Write a session_start entry so every JSONL file has a version header.
311
// For parent sessions with their own spans, also replay pending core events.
312
if (childInfo) {
313
// Child sessions get a minimal session_start (no core event replay)
314
this._bufferEntry(sessionId, {
315
v: 1,
316
ts: Date.now(),
317
dur: 0,
318
sid: sessionId,
319
type: 'session_start',
320
name: 'session_start',
321
spanId: `session-start-${sessionId}`,
322
status: 'ok',
323
attrs: {
324
copilotVersion: this._envService.getVersion(),
325
vscodeVersion: this._envService.vscodeVersion,
326
parentSessionId: childInfo.parentSessionId,
327
label: childInfo.label,
328
},
329
});
330
} else if (hasOwnSpans) {
331
this._emitSessionStartAndReplay(sessionId, session);
332
}
333
334
// Start auto-flush timer if this is the first active session
335
if (this._activeSessions.size === 1 && !this._autoFlushTimer) {
336
this._autoFlushTimer = setInterval(() => this._autoFlushAll(), this._autoFlushIntervalMs);
337
}
338
339
// Fire-and-forget cleanup of old logs
340
this._cleanupOldLogs().catch(() => { });
341
}
342
343
async endSession(sessionId: string): Promise<void> {
344
await this.flush(sessionId);
345
const session = this._activeSessions.get(sessionId);
346
if (session) {
347
this._totalBytesWritten += session.bytesWritten;
348
}
349
this._activeSessions.delete(sessionId);
350
351
// Clean up span→session mappings for this session
352
for (const [spanId, sid] of this._spanSessionIndex) {
353
if (sid === sessionId) {
354
this._spanSessionIndex.delete(spanId);
355
}
356
}
357
358
// Stop auto-flush timer if no active sessions remain
359
if (this._activeSessions.size === 0 && this._autoFlushTimer) {
360
clearInterval(this._autoFlushTimer);
361
this._autoFlushTimer = undefined;
362
}
363
}
364
365
async flush(sessionId: string): Promise<void> {
366
const session = this._activeSessions.get(sessionId);
367
if (!session) {
368
return;
369
}
370
371
if (session.buffer.length === 0) {
372
// No JSONL entries to flush, but still await any pending async work
373
// (e.g. model snapshot write) enqueued on flushPromise.
374
return session.flushPromise;
375
}
376
377
// Skip flushing for sessions not yet confirmed as main sessions.
378
// Keep the buffer intact so entries are preserved if the session
379
// is promoted later (e.g., when a child span references it).
380
if (!session.parentSessionId && !session.hasOwnSpans) {
381
return;
382
}
383
384
const lines = session.buffer.splice(0);
385
const content = lines.join('');
386
387
session.flushPromise = session.flushPromise.then(
388
() => this._writeToFile(session, content),
389
() => this._writeToFile(session, content),
390
);
391
return session.flushPromise;
392
}
393
394
getLogPath(sessionId: string): URI | undefined {
395
const active = this._activeSessions.get(sessionId);
396
if (active) {
397
return active.uri;
398
}
399
// For child sessions, construct the correct <label>-<sessionId>.jsonl path
400
const childInfo = this._childSessionMap.get(sessionId);
401
if (childInfo) {
402
const dir = this._getDebugLogsDir();
403
if (!dir) { return undefined; }
404
const parentDir = URI.joinPath(dir, childInfo.parentSessionId);
405
return URI.joinPath(parentDir, `${childInfo.label}-${sessionId}.jsonl`);
406
}
407
// For historical sessions (after restart), construct the default path
408
const sessionDir = this.getSessionDir(sessionId);
409
return sessionDir ? URI.joinPath(sessionDir, 'main.jsonl') : undefined;
410
}
411
412
getSessionDir(sessionId: string): URI | undefined {
413
// If active, use the stored sessionDir (already points to parent dir for children)
414
const active = this._activeSessions.get(sessionId);
415
if (active) {
416
return active.sessionDir;
417
}
418
// If known as a child, resolve to the parent's directory
419
const childInfo = this._childSessionMap.get(sessionId);
420
if (childInfo) {
421
const dir = this._getDebugLogsDir();
422
return dir ? URI.joinPath(dir, childInfo.parentSessionId) : undefined;
423
}
424
// Unknown session — construct the default path (assuming it's a parent)
425
const dir = this._getDebugLogsDir();
426
return dir ? URI.joinPath(dir, sessionId) : undefined;
427
}
428
429
getActiveSessionIds(): string[] {
430
return [...this._activeSessions.keys()];
431
}
432
433
isDebugLogUri(uri: URI): boolean {
434
const dir = this._getDebugLogsDir();
435
if (!dir) {
436
return false;
437
}
438
return extUriBiasedIgnorePathCase.isEqualOrParent(uri, dir);
439
}
440
441
getSessionDirForResource(sessionResource: URI): URI | undefined {
442
const sessionId = sessionResourceToId(sessionResource);
443
return this.getSessionDir(sessionId);
444
}
445
446
setModelSnapshot(models: readonly unknown[]): void {
447
this._modelSnapshot = models;
448
// Write to any active parent sessions that started before the model fetch completed
449
for (const [, session] of this._activeSessions) {
450
if (!session.parentSessionId && session.hasOwnSpans) {
451
this._enqueueModelSnapshotWrite(session);
452
}
453
}
454
}
455
456
private _enqueueModelSnapshotWrite(session: IActiveLogSession): void {
457
session.flushPromise = session.flushPromise.then(
458
() => this._writeModelSnapshot(session),
459
() => this._writeModelSnapshot(session),
460
);
461
}
462
463
private async _writeModelSnapshot(session: IActiveLogSession): Promise<void> {
464
if (!this._modelSnapshot || session.modelSnapshotWritten) {
465
return;
466
}
467
try {
468
if (!session.dirEnsured) {
469
await createDirectoryIfNotExists(this._fileSystemService, session.sessionDir);
470
session.dirEnsured = true;
471
}
472
const modelsUri = URI.joinPath(session.sessionDir, 'models.json');
473
await fs.promises.writeFile(modelsUri.fsPath, JSON.stringify(this._modelSnapshot, null, 2), 'utf-8');
474
session.modelSnapshotWritten = true;
475
} catch (err) {
476
this._logService.error('[ChatDebugFileLogger] Failed to write models.json', err);
477
}
478
}
479
480
private _enqueueFileWrite(session: IActiveLogSession, content: string, fileName: string): void {
481
session.flushPromise = session.flushPromise.then(
482
() => this._writeSessionFile(session, content, fileName),
483
() => this._writeSessionFile(session, content, fileName),
484
);
485
}
486
487
private async _writeSessionFile(session: IActiveLogSession, content: string, fileName: string): Promise<void> {
488
try {
489
if (!session.dirEnsured) {
490
await createDirectoryIfNotExists(this._fileSystemService, session.sessionDir);
491
session.dirEnsured = true;
492
}
493
const fileUri = URI.joinPath(session.sessionDir, fileName);
494
await fs.promises.writeFile(fileUri.fsPath, fileName.endsWith('.json') ? JSON.stringify({ content }, null, 2) : content, 'utf-8');
495
} catch (err) {
496
this._logService.error(`[ChatDebugFileLogger] Failed to write ${fileName}`, err);
497
}
498
}
499
500
/**
501
* Emit a session_start entry, replay cached core events, and write the model snapshot.
502
* Called when a parent session is first promoted to hasOwnSpans.
503
*/
504
private _emitSessionStartAndReplay(sessionId: string, session: IActiveLogSession): void {
505
this._bufferEntry(sessionId, {
506
v: 1,
507
ts: Date.now(),
508
dur: 0,
509
sid: sessionId,
510
type: 'session_start',
511
name: 'session_start',
512
spanId: `session-start-${sessionId}`,
513
status: 'ok',
514
attrs: {
515
copilotVersion: this._envService.getVersion(),
516
vscodeVersion: this._envService.vscodeVersion,
517
},
518
});
519
for (const entry of this._pendingCoreEvents) {
520
this._bufferEntry(sessionId, { ...entry, sid: sessionId });
521
}
522
if (this._modelSnapshot) {
523
this._enqueueModelSnapshotWrite(session);
524
}
525
// Write pending tool definitions that arrived before the session was promoted
526
if (session.pendingToolDefs) {
527
const fileName = `tools_${session.toolsIndex}.json`;
528
session.toolsIndex++;
529
session.currentToolsFile = fileName;
530
this._enqueueFileWrite(session, session.pendingToolDefs, fileName);
531
session.pendingToolDefs = undefined;
532
}
533
}
534
535
// ── OTel span handling ──
536
537
private _onSpanCompleted(span: ICompletedSpanData): void {
538
const sessionId = this._extractSessionId(span);
539
if (!sessionId) {
540
return;
541
}
542
543
// Record the span→session mapping so child spans can inherit it
544
this._spanSessionIndex.set(span.spanId, sessionId);
545
if (this._spanSessionIndex.size > MAX_SPAN_SESSION_INDEX) {
546
// Evict oldest entries (Map iterates in insertion order)
547
const excess = this._spanSessionIndex.size - MAX_SPAN_SESSION_INDEX;
548
const iter = this._spanSessionIndex.keys();
549
for (let i = 0; i < excess; i++) {
550
this._spanSessionIndex.delete(iter.next().value!);
551
}
552
}
553
554
// Check if this span carries parent session info (e.g., title, categorization)
555
const parentChatSessionId = asString(span.attributes[CopilotChatAttr.PARENT_CHAT_SESSION_ID]);
556
const debugLogLabel = asString(span.attributes[CopilotChatAttr.DEBUG_LOG_LABEL]);
557
if (parentChatSessionId && debugLogLabel && !this._childSessionMap.has(sessionId)) {
558
this._childSessionMap.set(sessionId, { parentSessionId: parentChatSessionId, label: debugLogLabel });
559
}
560
561
const entry = this._spanToEntry(span, sessionId);
562
const opName = asString(span.attributes[GenAiAttr.OPERATION_NAME]);
563
const outputMessages = opName === GenAiOperationName.CHAT
564
? asString(span.attributes[GenAiAttr.OUTPUT_MESSAGES])
565
: undefined;
566
567
// Never auto-promote sessions from OTel spans. Sub-requests like
568
// title generation, categorization, and progress-message generation
569
// each carry their own session IDs with real CHAT content but should
570
// not create top-level folders. A session is only promoted to "real"
571
// (hasOwnSpans = true) when:
572
// 1. startSession() is called explicitly, or
573
// 2. A child span references it via PARENT_CHAT_SESSION_ID
574
// (handled in _ensureSession's child branch).
575
// 3. The session directory already exists on disk (resumed after restart).
576
this._ensureSession(sessionId);
577
578
// Auto-promote resumed sessions: if the session was just created with
579
// hasOwnSpans = false but has an existing JSONL directory from a previous
580
// extension lifecycle, promote it. This handles sessions continued after
581
// VS Code restart where title/categorization won't re-fire.
582
const session = this._activeSessions.get(sessionId);
583
if (session && !session.hasOwnSpans && !session.parentSessionId && !session.resumeChecked) {
584
session.resumeChecked = true;
585
const mainJsonl = URI.joinPath(session.sessionDir, 'main.jsonl');
586
try {
587
fs.accessSync(mainJsonl.fsPath);
588
// Directory exists from a previous run — this is a resumed session
589
session.hasOwnSpans = true;
590
session.dirEnsured = true;
591
592
// Determine the run index: read the max rIdx from the existing file + 1
593
try {
594
const tail = this._readTailBytes(mainJsonl.fsPath, 8192);
595
let maxRIdx = 0;
596
for (const line of tail.split('\n')) {
597
if (!line.trim()) { continue; }
598
try {
599
const parsed = JSON.parse(line);
600
if (typeof parsed.rIdx === 'number' && parsed.rIdx > maxRIdx) {
601
maxRIdx = parsed.rIdx;
602
}
603
} catch { /* skip malformed lines */ }
604
}
605
session.runIndex = maxRIdx + 1;
606
} catch { /* file read failed — runIndex stays at 0, but that's safe since this is a back-compat path */ }
607
608
// Find the next available indices for companion files to avoid
609
// overwriting ones from the previous run. Single readdir + scan.
610
try {
611
for (const f of fs.readdirSync(session.sessionDir.fsPath)) {
612
const spIdx = f.startsWith('system_prompt_') ? parseInt(f.slice(14), 10) : -1;
613
if (spIdx >= session.systemPromptIndex) { session.systemPromptIndex = spIdx + 1; }
614
const tIdx = f.startsWith('tools_') ? parseInt(f.slice(6), 10) : -1;
615
if (tIdx >= session.toolsIndex) { session.toolsIndex = tIdx + 1; }
616
}
617
} catch { /* readdir failed — indices stay at 0 */ }
618
} catch {
619
// No existing directory — leave as is
620
}
621
}
622
623
// Write system_prompt JSON when model or mode changes (before buffering so llm_request gets the file ref)
624
if (opName === GenAiOperationName.CHAT) {
625
const session = this._activeSessions.get(sessionId);
626
if (session && session.hasOwnSpans && !session.parentSessionId) {
627
const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
628
?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
629
?? 'unknown';
630
const systemInstructions = asString(span.attributes[GenAiAttr.SYSTEM_INSTRUCTIONS]);
631
if (systemInstructions) {
632
const key = `${model}:${systemInstructions.length}`;
633
if (key !== session.systemPromptKey) {
634
const fileName = `system_prompt_${session.systemPromptIndex}.json`;
635
session.systemPromptKey = key;
636
session.systemPromptIndex++;
637
session.currentSystemPromptFile = fileName;
638
this._enqueueFileWrite(session, systemInstructions, fileName);
639
}
640
}
641
}
642
}
643
644
if (entry) {
645
// Attach current system prompt and tools file references to llm_request entries
646
if (entry.type === 'llm_request') {
647
const session = this._activeSessions.get(sessionId);
648
if (session?.currentSystemPromptFile) {
649
entry.attrs.systemPromptFile = session.currentSystemPromptFile;
650
}
651
if (session?.currentToolsFile) {
652
entry.attrs.toolsFile = session.currentToolsFile;
653
}
654
}
655
this._bufferEntry(sessionId, entry);
656
}
657
658
// Note: user_message events are captured in real-time via _onSpanEvent
659
// (onDidEmitSpanEvent) to avoid duplicates, since span.events also
660
// contains them after completion.
661
662
// Extract agent_response from output messages (on chat spans)
663
if (opName === GenAiOperationName.CHAT) {
664
// Extract agent response summary from output messages
665
if (outputMessages) {
666
const reasoningContent = asString(span.attributes[CopilotChatAttr.REASONING_CONTENT]);
667
this._bufferEntry(sessionId, {
668
ts: span.endTime,
669
dur: 0,
670
sid: sessionId,
671
type: 'agent_response',
672
name: 'agent_response',
673
spanId: `agent-msg-${span.spanId}`,
674
parentSpanId: span.parentSpanId,
675
status: 'ok',
676
attrs: {
677
response: truncate(outputMessages, MAX_ATTR_VALUE_LENGTH),
678
...(reasoningContent ? { reasoning: truncate(reasoningContent, MAX_ATTR_VALUE_LENGTH) } : {}),
679
},
680
});
681
}
682
}
683
}
684
685
private _onSpanEvent(event: ISpanEventData): void {
686
if (event.eventName === 'turn_start' || event.eventName === 'turn_end') {
687
this._onTurnBoundaryEvent(event);
688
return;
689
}
690
691
if (event.eventName === 'tools_available') {
692
this._onToolsAvailableEvent(event);
693
return;
694
}
695
696
if (event.eventName !== 'user_message') {
697
return;
698
}
699
const content = event.attributes.content;
700
if (!content || (typeof content === 'string' && !content.trim())) {
701
return;
702
}
703
704
// If the event carries a session ID, route to that specific session
705
const eventSessionId = event.attributes[CopilotChatAttr.CHAT_SESSION_ID];
706
if (typeof eventSessionId === 'string') {
707
// Ensure the session buffer exists so early events (before any span completes) are captured
708
this._ensureSession(eventSessionId);
709
this._bufferEntry(eventSessionId, {
710
ts: event.timestamp,
711
dur: 0,
712
sid: eventSessionId,
713
type: 'user_message',
714
name: 'user_message',
715
spanId: event.spanId,
716
parentSpanId: event.parentSpanId,
717
status: 'ok',
718
attrs: {
719
content: truncate(String(content), MAX_ATTR_VALUE_LENGTH),
720
},
721
});
722
return;
723
}
724
725
// Fallback: try to inherit session from parent span before broadcasting
726
const inheritedSessionId = event.parentSpanId ? this._spanSessionIndex.get(event.parentSpanId) : undefined;
727
if (inheritedSessionId && this._activeSessions.has(inheritedSessionId)) {
728
this._bufferEntry(inheritedSessionId, {
729
ts: event.timestamp,
730
dur: 0,
731
sid: inheritedSessionId,
732
type: 'user_message',
733
name: 'user_message',
734
spanId: event.spanId,
735
parentSpanId: event.parentSpanId,
736
status: 'ok',
737
attrs: {
738
content: truncate(String(content), MAX_ATTR_VALUE_LENGTH),
739
},
740
});
741
return;
742
}
743
744
// Last resort: span events without chat_session_id — write to parent sessions that have their own spans
745
const parentSessions = [...this._activeSessions.entries()]
746
.filter(([, session]) => !session.parentSessionId && session.hasOwnSpans)
747
.map(([id]) => id);
748
if (parentSessions.length === 0) {
749
return;
750
}
751
752
for (const sessionId of parentSessions) {
753
const entry: IDebugLogEntry = {
754
ts: event.timestamp,
755
dur: 0,
756
sid: sessionId,
757
type: 'user_message',
758
name: 'user_message',
759
spanId: event.spanId,
760
parentSpanId: event.parentSpanId,
761
status: 'ok',
762
attrs: {
763
content: truncate(String(content), MAX_ATTR_VALUE_LENGTH),
764
},
765
};
766
this._bufferEntry(sessionId, entry);
767
}
768
}
769
770
private _onTurnBoundaryEvent(event: ISpanEventData): void {
771
const type = event.eventName === 'turn_start' ? 'turn_start' : 'turn_end';
772
const turnId = typeof event.attributes.turnId === 'string' ? event.attributes.turnId : String(event.attributes.turnId ?? '');
773
const sessionId = typeof event.attributes[CopilotChatAttr.CHAT_SESSION_ID] === 'string'
774
? event.attributes[CopilotChatAttr.CHAT_SESSION_ID] as string
775
: (event.parentSpanId ? this._spanSessionIndex.get(event.parentSpanId) : undefined);
776
777
if (!sessionId) {
778
return;
779
}
780
781
// Ensure the session buffer exists so early turn events are captured
782
this._ensureSession(sessionId);
783
784
this._bufferEntry(sessionId, {
785
ts: event.timestamp,
786
dur: 0,
787
sid: sessionId,
788
type,
789
name: `${type}:${turnId}`,
790
spanId: `${type}-${event.spanId}-${turnId}`,
791
parentSpanId: event.parentSpanId,
792
status: 'ok',
793
attrs: { turnId },
794
});
795
}
796
797
private _onToolsAvailableEvent(event: ISpanEventData): void {
798
const sessionId = typeof event.attributes[CopilotChatAttr.CHAT_SESSION_ID] === 'string'
799
? event.attributes[CopilotChatAttr.CHAT_SESSION_ID] as string
800
: (event.parentSpanId ? this._spanSessionIndex.get(event.parentSpanId) : undefined);
801
802
if (!sessionId) {
803
return;
804
}
805
806
// Do NOT create sessions from tools_available events — they can carry tool call IDs
807
// (e.g., toolu_xxx, call_xxx) as conversation IDs, which are not valid session IDs.
808
const session = this._activeSessions.get(sessionId);
809
if (!session || session.parentSessionId) {
810
return;
811
}
812
813
// If the session isn't promoted yet, cache the tools for later replay
814
if (!session.hasOwnSpans) {
815
const toolDefs = typeof event.attributes.toolDefinitions === 'string' ? event.attributes.toolDefinitions : undefined;
816
if (toolDefs) {
817
session.pendingToolDefs = toolDefs;
818
}
819
return;
820
}
821
822
const toolDefs = typeof event.attributes.toolDefinitions === 'string' ? event.attributes.toolDefinitions : undefined;
823
if (!toolDefs) {
824
return;
825
}
826
827
// Use the content length to detect changes. Different tool sets (from model
828
// or mode switches) will have different lengths. A false negative (same length,
829
// different content) just means we skip writing a redundant file — harmless.
830
const key = `tools:${toolDefs.length}`;
831
if (key !== session.toolsKey) {
832
const fileName = `tools_${session.toolsIndex}.json`;
833
session.toolsKey = key;
834
session.toolsIndex++;
835
session.currentToolsFile = fileName;
836
this._enqueueFileWrite(session, toolDefs, fileName);
837
}
838
}
839
840
// ── Core debug event handling (discovery, skill loading, etc.) ──
841
842
private _onCoreDebugEvent(event: vscode.ChatDebugEvent): void {
843
// Only capture discovery/generic events from core — tool calls, model turns,
844
// and subagent invocations come from OTel spans which are the source of truth.
845
if (!(event instanceof vscode.ChatDebugGenericEvent)) {
846
return;
847
}
848
849
const timestamp = event.created.getTime();
850
const eventId = event.id;
851
const parentEventId = event.parentEventId;
852
853
const entry: IDebugLogEntry = {
854
ts: timestamp,
855
dur: 0,
856
sid: '',
857
type: event.category === 'discovery' ? 'discovery' : 'generic',
858
name: event.name,
859
spanId: eventId ?? `core-${Date.now()}`,
860
parentSpanId: parentEventId,
861
status: event.level === vscode.ChatDebugLogLevel.Error ? 'error' : 'ok',
862
attrs: {
863
...(event.details ? { details: truncate(event.details, MAX_ATTR_VALUE_LENGTH) } : {}),
864
...(event.category ? { category: event.category } : {}),
865
source: 'core',
866
},
867
};
868
869
// Core events may arrive before any session exists — cache and replay.
870
// Cap the buffer to avoid unbounded growth over long-running sessions.
871
if (this._pendingCoreEvents.length >= MAX_PENDING_CORE_EVENTS) {
872
this._pendingCoreEvents.shift();
873
}
874
this._pendingCoreEvents.push(entry);
875
// Only write to parent sessions that have their own spans
876
for (const [sessionId, session] of this._activeSessions.entries()) {
877
if (!session.parentSessionId && session.hasOwnSpans) {
878
this._bufferEntry(sessionId, { ...entry, sid: sessionId });
879
}
880
}
881
}
882
883
// ── Span to entry conversion ──
884
885
private _spanToEntry(span: ICompletedSpanData, sessionId: string): IDebugLogEntry | undefined {
886
const opName = asString(span.attributes[GenAiAttr.OPERATION_NAME]);
887
const duration = span.endTime - span.startTime;
888
const isError = span.status.code === SpanStatusCode.ERROR;
889
890
switch (opName) {
891
case GenAiOperationName.EXECUTE_TOOL: {
892
const toolName = asString(span.attributes[GenAiAttr.TOOL_NAME]) ?? span.name;
893
return {
894
ts: span.startTime,
895
dur: duration,
896
sid: sessionId,
897
type: 'tool_call',
898
name: toolName,
899
spanId: span.spanId,
900
parentSpanId: span.parentSpanId,
901
status: isError ? 'error' : 'ok',
902
attrs: {
903
...(span.attributes[GenAiAttr.TOOL_CALL_ARGUMENTS] !== undefined
904
? { args: truncate(String(span.attributes[GenAiAttr.TOOL_CALL_ARGUMENTS]), MAX_ATTR_VALUE_LENGTH) }
905
: {}),
906
...(span.attributes[GenAiAttr.TOOL_CALL_RESULT] !== undefined
907
? { result: truncate(String(span.attributes[GenAiAttr.TOOL_CALL_RESULT]), MAX_ATTR_VALUE_LENGTH) }
908
: {}),
909
...(isError && span.status.message ? { error: span.status.message } : {}),
910
},
911
};
912
}
913
914
case GenAiOperationName.CHAT: {
915
const model = asString(span.attributes[GenAiAttr.REQUEST_MODEL])
916
?? asString(span.attributes[GenAiAttr.RESPONSE_MODEL])
917
?? 'unknown';
918
return {
919
ts: span.startTime,
920
dur: duration,
921
sid: sessionId,
922
type: 'llm_request',
923
name: `chat:${model}`,
924
spanId: span.spanId,
925
parentSpanId: span.parentSpanId,
926
status: isError ? 'error' : 'ok',
927
attrs: {
928
model,
929
...(span.attributes[GenAiAttr.USAGE_INPUT_TOKENS] !== undefined
930
? { inputTokens: asNumber(span.attributes[GenAiAttr.USAGE_INPUT_TOKENS]) }
931
: {}),
932
...(span.attributes[GenAiAttr.USAGE_OUTPUT_TOKENS] !== undefined
933
? { outputTokens: asNumber(span.attributes[GenAiAttr.USAGE_OUTPUT_TOKENS]) }
934
: {}),
935
...(span.attributes[GenAiAttr.USAGE_CACHE_READ_INPUT_TOKENS] !== undefined
936
? { cachedTokens: asNumber(span.attributes[GenAiAttr.USAGE_CACHE_READ_INPUT_TOKENS]) }
937
: {}),
938
...(span.attributes[CopilotChatAttr.TIME_TO_FIRST_TOKEN] !== undefined
939
? { ttft: asNumber(span.attributes[CopilotChatAttr.TIME_TO_FIRST_TOKEN]) }
940
: {}),
941
...(span.attributes[CopilotChatAttr.USER_REQUEST] !== undefined
942
? { userRequest: String(span.attributes[CopilotChatAttr.USER_REQUEST]) }
943
: {}),
944
...(span.attributes[GenAiAttr.INPUT_MESSAGES] !== undefined
945
? { inputMessages: String(span.attributes[GenAiAttr.INPUT_MESSAGES]) }
946
: {}),
947
...(span.attributes[GenAiAttr.REQUEST_MAX_TOKENS] !== undefined
948
? { maxTokens: asNumber(span.attributes[GenAiAttr.REQUEST_MAX_TOKENS]) }
949
: {}),
950
...(span.attributes[GenAiAttr.REQUEST_TEMPERATURE] !== undefined
951
? { temperature: asNumber(span.attributes[GenAiAttr.REQUEST_TEMPERATURE]) }
952
: {}),
953
...(span.attributes[GenAiAttr.REQUEST_TOP_P] !== undefined
954
? { topP: asNumber(span.attributes[GenAiAttr.REQUEST_TOP_P]) }
955
: {}),
956
...(isError && span.status.message ? { error: span.status.message } : {}),
957
},
958
};
959
}
960
961
case GenAiOperationName.INVOKE_AGENT: {
962
if (!span.parentSpanId) {
963
return undefined; // Top-level agent spans are containers
964
}
965
const agentName = asString(span.attributes[GenAiAttr.AGENT_NAME]) ?? span.name;
966
return {
967
ts: span.startTime,
968
dur: duration,
969
sid: sessionId,
970
type: 'subagent',
971
name: agentName,
972
spanId: span.spanId,
973
parentSpanId: span.parentSpanId,
974
status: isError ? 'error' : 'ok',
975
attrs: {
976
agentName,
977
...(span.attributes[GenAiAttr.AGENT_DESCRIPTION] !== undefined
978
? { description: truncate(String(span.attributes[GenAiAttr.AGENT_DESCRIPTION]), MAX_ATTR_VALUE_LENGTH) }
979
: {}),
980
...(isError && span.status.message ? { error: span.status.message } : {}),
981
},
982
};
983
}
984
985
case GenAiOperationName.CONTENT_EVENT:
986
case 'core_event': {
987
const name = asString(span.attributes[CopilotChatAttr.DEBUG_NAME]) ?? span.name;
988
return {
989
ts: span.startTime,
990
dur: duration,
991
sid: sessionId,
992
type: 'generic',
993
name,
994
spanId: span.spanId,
995
parentSpanId: span.parentSpanId,
996
status: isError ? 'error' : 'ok',
997
attrs: {
998
...(span.attributes['copilot_chat.event_details'] !== undefined
999
? { details: truncate(String(span.attributes['copilot_chat.event_details']), MAX_ATTR_VALUE_LENGTH) }
1000
: {}),
1001
...(span.attributes['copilot_chat.event_category'] !== undefined
1002
? { category: String(span.attributes['copilot_chat.event_category']) }
1003
: {}),
1004
},
1005
};
1006
}
1007
1008
case GenAiOperationName.EXECUTE_HOOK: {
1009
const hookType = asString(span.attributes[CopilotChatAttr.HOOK_TYPE]) ?? span.name;
1010
return {
1011
ts: span.startTime,
1012
dur: duration,
1013
sid: sessionId,
1014
type: 'hook',
1015
name: hookType,
1016
spanId: span.spanId,
1017
parentSpanId: span.parentSpanId,
1018
status: isError ? 'error' : 'ok',
1019
attrs: {
1020
...(span.attributes['copilot_chat.hook_command'] !== undefined
1021
? { command: truncate(String(span.attributes['copilot_chat.hook_command']), MAX_ATTR_VALUE_LENGTH) }
1022
: {}),
1023
...(span.attributes[CopilotChatAttr.HOOK_INPUT] !== undefined
1024
? { input: truncate(String(span.attributes[CopilotChatAttr.HOOK_INPUT]), MAX_ATTR_VALUE_LENGTH) }
1025
: {}),
1026
...(span.attributes[CopilotChatAttr.HOOK_OUTPUT] !== undefined
1027
? { output: truncate(String(span.attributes[CopilotChatAttr.HOOK_OUTPUT]), MAX_ATTR_VALUE_LENGTH) }
1028
: {}),
1029
...(span.attributes[CopilotChatAttr.HOOK_RESULT_KIND] !== undefined
1030
? { resultKind: String(span.attributes[CopilotChatAttr.HOOK_RESULT_KIND]) }
1031
: {}),
1032
...(isError && span.status.message ? { error: span.status.message } : {}),
1033
},
1034
};
1035
}
1036
1037
default:
1038
return undefined;
1039
}
1040
}
1041
1042
// ── Helpers ──
1043
1044
/**
1045
* Read the last `byteCount` bytes of a file synchronously.
1046
* Used during session resume to determine the max rIdx without reading the entire file.
1047
*/
1048
private _readTailBytes(filePath: string, byteCount: number): string {
1049
const fd = fs.openSync(filePath, 'r');
1050
try {
1051
const stat = fs.fstatSync(fd);
1052
const start = Math.max(0, stat.size - byteCount);
1053
const buf = Buffer.alloc(Math.min(byteCount, stat.size));
1054
fs.readSync(fd, buf, 0, buf.length, start);
1055
return buf.toString('utf-8');
1056
} finally {
1057
fs.closeSync(fd);
1058
}
1059
}
1060
1061
private _extractSessionId(span: ICompletedSpanData): string | undefined {
1062
const directSessionId = asString(span.attributes[CopilotChatAttr.CHAT_SESSION_ID])
1063
?? asString(span.attributes[GenAiAttr.CONVERSATION_ID]);
1064
1065
// If the span's parentSpanId maps to a known child session, prefer that.
1066
// This handles hook spans that carry the parent's CHAT_SESSION_ID but
1067
// whose parent span belongs to a child subagent session.
1068
if (span.parentSpanId) {
1069
const childSessionId = this._spanSessionIndex.get(span.parentSpanId);
1070
if (childSessionId && this._childSessionMap.has(childSessionId)) {
1071
return childSessionId;
1072
}
1073
}
1074
1075
return directSessionId
1076
?? (span.parentSpanId ? this._spanSessionIndex.get(span.parentSpanId) : undefined);
1077
}
1078
1079
private _bufferEntry(sessionId: string, entry: IDebugLogEntry): void {
1080
const session = this._activeSessions.get(sessionId);
1081
if (!session) {
1082
return;
1083
}
1084
let stamped = entry;
1085
// Stamp run index for restart scoping (omit when 0 to save bytes)
1086
if (session.runIndex > 0 && !stamped.rIdx) {
1087
stamped = { ...stamped, rIdx: session.runIndex };
1088
}
1089
session.buffer.push(JSON.stringify(stamped) + '\n');
1090
this._onDidEmitEntry.fire({ sessionId, entry: stamped });
1091
}
1092
1093
async readEntries(sessionId: string): Promise<IDebugLogEntry[]> {
1094
const entries: IDebugLogEntry[] = [];
1095
await this.streamEntries(sessionId, entry => entries.push(entry));
1096
return entries;
1097
}
1098
1099
async readTailEntries(sessionId: string, count: number): Promise<IDebugLogEntry[]> {
1100
const session = this._activeSessions.get(sessionId);
1101
const logPath = session?.uri ?? this.getLogPath(sessionId);
1102
let entries: IDebugLogEntry[] = [];
1103
1104
if (logPath) {
1105
try {
1106
const stat = await fs.promises.stat(logPath.fsPath);
1107
// Start with a read size that should cover `count` entries.
1108
// Average JSONL entry is ~1-2KB, so count * 4KB is generous.
1109
const readSize = Math.min(stat.size, count * 4096);
1110
const startOffset = Math.max(0, stat.size - readSize);
1111
1112
const fd = await fs.promises.open(logPath.fsPath, 'r');
1113
try {
1114
const buffer = Buffer.alloc(stat.size - startOffset);
1115
const { bytesRead } = await fd.read(buffer, 0, buffer.length, startOffset);
1116
1117
const text = buffer.subarray(0, bytesRead).toString('utf-8');
1118
const lines = text.split('\n');
1119
// Skip the first line if we started mid-file (likely partial)
1120
const startIdx = startOffset > 0 ? 1 : 0;
1121
for (let i = startIdx; i < lines.length; i++) {
1122
if (!lines[i]) { continue; }
1123
try {
1124
entries.push(JSON.parse(lines[i]) as IDebugLogEntry);
1125
} catch { /* skip malformed */ }
1126
}
1127
} finally {
1128
await fd.close();
1129
}
1130
1131
// Keep only the last `count` entries
1132
if (entries.length > count) {
1133
entries = entries.slice(-count);
1134
}
1135
} catch {
1136
// File may not exist — that's fine
1137
}
1138
}
1139
1140
// Append unflushed buffer entries
1141
if (session) {
1142
for (const line of session.buffer) {
1143
try {
1144
entries.push(JSON.parse(line) as IDebugLogEntry);
1145
} catch { /* skip malformed */ }
1146
}
1147
}
1148
1149
// Trim to the last `count` entries (file + buffer combined)
1150
if (entries.length > count) {
1151
entries = entries.slice(-count);
1152
}
1153
1154
return entries;
1155
}
1156
1157
async streamEntries(sessionId: string, onEntry: (entry: IDebugLogEntry) => void): Promise<void> {
1158
const session = this._activeSessions.get(sessionId);
1159
const logPath = session?.uri ?? this.getLogPath(sessionId);
1160
1161
if (logPath) {
1162
try {
1163
await new Promise<void>((resolve, reject) => {
1164
const stream = fs.createReadStream(logPath.fsPath, { encoding: 'utf-8' });
1165
let partial = '';
1166
stream.on('data', (chunk) => {
1167
const text = typeof chunk === 'string' ? chunk : chunk.toString('utf-8');
1168
partial += text;
1169
const lines = partial.split('\n');
1170
// Last element may be a partial line — keep it for next chunk
1171
partial = lines.pop() ?? '';
1172
for (const line of lines) {
1173
if (!line) { continue; }
1174
try {
1175
onEntry(JSON.parse(line) as IDebugLogEntry);
1176
} catch { /* skip malformed */ }
1177
}
1178
});
1179
stream.on('end', () => {
1180
// Process any remaining partial line
1181
if (partial) {
1182
try {
1183
onEntry(JSON.parse(partial) as IDebugLogEntry);
1184
} catch { /* skip malformed */ }
1185
}
1186
resolve();
1187
});
1188
stream.on('error', reject);
1189
});
1190
} catch {
1191
// File may not exist — that's fine
1192
}
1193
}
1194
1195
// Append unflushed buffer entries
1196
if (session) {
1197
for (const line of session.buffer) {
1198
try {
1199
onEntry(JSON.parse(line) as IDebugLogEntry);
1200
} catch { /* skip malformed */ }
1201
}
1202
}
1203
}
1204
1205
private async _writeToFile(session: IActiveLogSession, content: string): Promise<void> {
1206
try {
1207
if (!session.dirEnsured) {
1208
await createDirectoryIfNotExists(this._fileSystemService, session.sessionDir);
1209
session.dirEnsured = true;
1210
}
1211
await fs.promises.appendFile(session.uri.fsPath, content, 'utf-8');
1212
session.bytesWritten += Buffer.byteLength(content, 'utf-8');
1213
if (session.bytesWritten > this._maxSessionLogBytes) {
1214
await this._truncateLogFile(session);
1215
}
1216
} catch (err) {
1217
this._logService.error('[ChatDebugFileLogger] Failed to write debug log entries', err);
1218
}
1219
}
1220
1221
/**
1222
* Truncate a log file to retain the newest portion (TRUNCATION_RETAIN_RATIO
1223
* of the configured max size) using a streaming approach via a temp file
1224
* to avoid loading the entire tail into memory.
1225
*/
1226
private async _truncateLogFile(session: IActiveLogSession): Promise<void> {
1227
try {
1228
const filePath = session.uri.fsPath;
1229
const stat = await fs.promises.stat(filePath);
1230
if (stat.size <= this._maxSessionLogBytes) {
1231
return;
1232
}
1233
1234
const retainBytes = Math.floor(this._maxSessionLogBytes * TRUNCATION_RETAIN_RATIO);
1235
const skipBytes = stat.size - retainBytes;
1236
const fd = await fs.promises.open(filePath, 'r');
1237
try {
1238
// Read a small probe around the cut point to find the next newline
1239
const probe = Buffer.alloc(4096);
1240
const { bytesRead } = await fd.read(probe, 0, probe.length, skipBytes);
1241
const newlineIdx = probe.indexOf(0x0A, 0); // '\n'
1242
const cutOffset = skipBytes + (newlineIdx >= 0 && newlineIdx < bytesRead ? newlineIdx + 1 : 0);
1243
1244
const tailSize = stat.size - cutOffset;
1245
if (tailSize <= 0) {
1246
await fd.close();
1247
return;
1248
}
1249
await fd.close();
1250
1251
// Stream the tail to a temp file, then rename over the original.
1252
const tmpPath = filePath + '.tmp';
1253
await new Promise<void>((resolve, reject) => {
1254
const readStream = fs.createReadStream(filePath, { start: cutOffset });
1255
const writeStream = fs.createWriteStream(tmpPath);
1256
const onError = (err: Error) => {
1257
readStream.destroy();
1258
writeStream.destroy();
1259
reject(err);
1260
};
1261
readStream.on('error', onError);
1262
writeStream.on('error', onError);
1263
writeStream.on('finish', resolve);
1264
readStream.pipe(writeStream);
1265
});
1266
await fs.promises.rename(tmpPath, filePath);
1267
session.bytesWritten = tailSize;
1268
/* __GDPR__
1269
"chatDebugFileLogger.truncated" : {
1270
"owner": "vijayupadya",
1271
"comment": "A debug log file was truncated due to size limits",
1272
"previousSize": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "File size in bytes before truncation" },
1273
"retainedSize": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "File size in bytes after truncation" }
1274
}
1275
*/
1276
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.truncated', undefined, { previousSize: stat.size, retainedSize: tailSize });
1277
} catch (innerErr) {
1278
await fd.close().catch(() => { });
1279
// Clean up temp file if it exists
1280
await fs.promises.unlink(filePath + '.tmp').catch(() => { });
1281
throw innerErr;
1282
}
1283
} catch (err) {
1284
this._logService.warn(`[ChatDebugFileLogger] Failed to truncate log file: ${err}`);
1285
/* __GDPR__
1286
"chatDebugFileLogger.truncateFailed" : {
1287
"owner": "vijayupadya",
1288
"comment": "Failed to truncate a debug log file"
1289
}
1290
*/
1291
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.truncateFailed');
1292
}
1293
}
1294
1295
private _autoFlushAll(): void {
1296
for (const sessionId of this._activeSessions.keys()) {
1297
this.flush(sessionId).catch(() => { });
1298
}
1299
}
1300
1301
private _restartFlushTimer(): void {
1302
if (this._autoFlushTimer) {
1303
clearInterval(this._autoFlushTimer);
1304
this._autoFlushTimer = undefined;
1305
}
1306
if (this._activeSessions.size > 0) {
1307
this._autoFlushTimer = setInterval(() => this._autoFlushAll(), this._autoFlushIntervalMs);
1308
}
1309
}
1310
1311
async listSessionIds(): Promise<string[]> {
1312
const dir = this._getDebugLogsDir();
1313
if (!dir) {
1314
return [];
1315
}
1316
try {
1317
const entries = await this._fileSystemService.readDirectory(dir);
1318
const dirs = entries.filter(([, type]) => type === 2 /* FileType.Directory */);
1319
1320
// Stat each directory in parallel to sort by most recently modified.
1321
const withMtime = await Promise.all(dirs.map(async ([name]) => {
1322
try {
1323
const stat = await this._fileSystemService.stat(URI.joinPath(dir, name));
1324
return { name, mtime: stat.mtime };
1325
} catch {
1326
return { name, mtime: 0 };
1327
}
1328
}));
1329
withMtime.sort((a, b) => b.mtime - a.mtime);
1330
return withMtime.map(e => e.name);
1331
} catch {
1332
return [];
1333
}
1334
}
1335
1336
private async _cleanupOldLogs(): Promise<void> {
1337
const dir = this._getDebugLogsDir();
1338
if (!dir) {
1339
return;
1340
}
1341
1342
const startTime = Date.now();
1343
try {
1344
const entries = await this._fileSystemService.readDirectory(dir);
1345
// Count both directories (new format) and legacy .jsonl files (old format)
1346
const sessionEntries = entries.filter(([name, type]) =>
1347
(type === 2 /* FileType.Directory */) ||
1348
(name.endsWith('.jsonl') && type === 1 /* FileType.File */)
1349
);
1350
1351
const configuredMax = this._configurationService.getExperimentBasedConfig(ConfigKey.Advanced.ChatDebugFileLoggingMaxRetainedSessionLogs, this._experimentationService);
1352
const maxRetainedSessionLogs = Number.isFinite(configuredMax) && configuredMax >= 1 ? Math.trunc(configuredMax) : DEFAULT_MAX_RETAINED_LOGS;
1353
if (sessionEntries.length <= maxRetainedSessionLogs) {
1354
/* __GDPR__
1355
"chatDebugFileLogger.cleanupOldLogs" : {
1356
"owner": "vijayupadya",
1357
"comment": "Old debug log files were cleaned up",
1358
"durationMs": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "Time in ms to perform cleanup" },
1359
"entryCount": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "Total number of log entries found" },
1360
"deletedCount": { "classification": "SystemMetaData", "purpose": "PerformanceAndHealth", "isMeasurement": true, "comment": "Number of log entries deleted" }
1361
}
1362
*/
1363
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.cleanupOldLogs', undefined, { durationMs: Date.now() - startTime, entryCount: sessionEntries.length, deletedCount: 0 });
1364
return;
1365
}
1366
1367
const entryStats = await Promise.all(
1368
sessionEntries.map(async ([name, type]) => {
1369
const entryUri = URI.joinPath(dir, name);
1370
const sessionIdFromEntry = name.replace('.jsonl', '');
1371
try {
1372
const stat = await this._fileSystemService.stat(entryUri);
1373
return { name, uri: entryUri, mtime: stat.mtime, sessionId: sessionIdFromEntry, isDir: type === 2 };
1374
} catch {
1375
return { name, uri: entryUri, mtime: 0, sessionId: sessionIdFromEntry, isDir: type === 2 };
1376
}
1377
}),
1378
);
1379
1380
entryStats.sort((a, b) => a.mtime - b.mtime);
1381
1382
const toDelete = entryStats.length - maxRetainedSessionLogs;
1383
let deleted = 0;
1384
for (const entry of entryStats) {
1385
if (deleted >= toDelete) {
1386
break;
1387
}
1388
if (this._activeSessions.has(entry.sessionId)) {
1389
continue;
1390
}
1391
try {
1392
await this._fileSystemService.delete(entry.uri, { recursive: true });
1393
deleted++;
1394
} catch {
1395
this._logService.warn(`[ChatDebugFileLogger] Failed to delete old debug log: ${entry.name}`);
1396
}
1397
}
1398
// GDPR comment above covers this event
1399
this._telemetryService.sendMSFTTelemetryEvent('chatDebugFileLogger.cleanupOldLogs', undefined, { durationMs: Date.now() - startTime, entryCount: sessionEntries.length, deletedCount: deleted });
1400
} catch {
1401
// Directory may not exist yet
1402
}
1403
}
1404
}
1405
1406
/**
1407
* Contribution that eagerly instantiates the ChatDebugFileLoggerService
1408
* so it starts listening to OTel events at activation time.
1409
*/
1410
export class ChatDebugFileLoggerContribution implements IExtensionContribution {
1411
public readonly id = 'chatDebugFileLoggerContribution';
1412
1413
constructor(
1414
@IChatDebugFileLoggerService _service: IChatDebugFileLoggerService,
1415
) {
1416
// The DI resolution of IChatDebugFileLoggerService triggers
1417
// construction of the singleton, which subscribes to events.
1418
}
1419
}
1420
1421
function asString(v: unknown): string | undefined {
1422
return typeof v === 'string' ? v : undefined;
1423
}
1424
1425
function asNumber(v: unknown): number | undefined {
1426
return typeof v === 'number' ? v : undefined;
1427
}
1428
1429
function truncate(s: string, maxLen: number): string {
1430
return s.length > maxLen ? s.slice(0, maxLen) + '[truncated]' : s;
1431
}
1432
1433