Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions .github/copilot-instructions.md
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,21 @@ The entire extension's logic is contained within the `CopilotTokenTracker` class
- **Focused Modifications**: Make surgical, precise changes that address the specific requirements without affecting other functionality.
- **Preserve Existing Structure**: Maintain the existing code organization and file structure. Don't refactor or reorganize code unless it's essential for the task.

## Logging Best Practices

**CRITICAL**: Do NOT add debug logging statements like `log('[DEBUG] message')` for troubleshooting during development. This approach has been found to interfere with the output channel and can hide existing log messages from appearing.

- **Use Existing Logs**: The extension already has comprehensive logging throughout. Review existing log statements to understand what's being tracked.
- **Minimal Logging**: Only add logging if absolutely necessary for a new feature. Keep messages concise and informative.
- **Remove Debug Logs**: Any temporary debug logging added during development MUST be removed before committing code.
- **Log Methods**: Use the appropriate method for the severity:
- `log(message)` - Standard informational messages
- `warn(message)` - Warnings or recoverable errors
- `error(message)` - Critical errors
- **No Debug Prefixes**: Avoid prefixing messages with `[DEBUG]` or similar markers. The log output is already timestamped and categorized.

If you need to troubleshoot execution flow, prefer using VS Code's debugger with breakpoints rather than adding log statements.

## Key Files & Conventions

- **`src/extension.ts`**: The single source file containing all logic.
Expand Down
6 changes: 4 additions & 2 deletions src/backend/facade.ts
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,8 @@ export class BackendFacade {
getCopilotSessionFiles: deps.getCopilotSessionFiles,
estimateTokensFromText: deps.estimateTokensFromText,
getModelFromRequest: deps.getModelFromRequest,
getSessionFileDataCached: deps.getSessionFileDataCached
getSessionFileDataCached: deps.getSessionFileDataCached,
updateTokenStats: deps.updateTokenStats
},
this.credentialService,
this.dataPlaneService,
Expand Down Expand Up @@ -226,6 +227,7 @@ export class BackendFacade {
const settings = this.getSettings();
const result = await this.syncService.syncToBackendStore(force, settings, this.isConfigured(settings));
this.clearQueryCache();
// UI update is now handled by syncService after successful completion
return result;
}

Expand Down Expand Up @@ -478,8 +480,8 @@ export class BackendFacade {
const next = applyDraftToSettings(previousSettings, draft, consentAt);
await this.updateConfiguration(next);
this.startTimerIfEnabled();
this.deps.updateTokenStats?.();
this.clearQueryCache();
// UI update happens automatically after sync completes via syncService callback
return { state: await this.getConfigPanelState(), message: 'Settings saved.' };
}

Expand Down
196 changes: 163 additions & 33 deletions src/backend/services/syncService.ts
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,8 @@ export interface SyncServiceDeps {
getModelFromRequest: (request: ChatRequest) => string;
// Cache integration for performance
getSessionFileDataCached?: (sessionFilePath: string, mtime: number) => Promise<SessionFileCache>;
// UI refresh callback after successful sync
updateTokenStats?: () => Promise<void>;
}

/**
Expand Down Expand Up @@ -128,8 +130,8 @@ export class SyncService {
}
});
}, intervalMs);
// Immediate initial sync
this.syncToBackendStore(false, settings, isConfigured).catch((e) => {
// Immediate initial sync (forced to ensure settings changes take effect)
this.syncToBackendStore(true, settings, isConfigured).catch((e) => {
this.deps.warn(`Backend sync initial sync failed: ${e?.message ?? e}`);
});
} catch (e) {
Expand Down Expand Up @@ -163,17 +165,23 @@ export class SyncService {
}

/**
* Process a session file using cached data.
* Process a session file using cached data for token counts but extracting accurate timestamps.
* Returns true if successful, false if cache miss (caller should parse file).
* Validates all cached data at runtime to prevent injection/corruption.
*
* CRITICAL: We parse the file to extract actual interaction timestamps and create per-day
* rollups, but use cached token counts for performance. This ensures accurate day assignment
* while still benefiting from cached calculations.
*/
private async processCachedSessionFile(
sessionFile: string,
fileMtimeMs: number,
workspaceId: string,
machineId: string,
userId: string | undefined,
rollups: Map<string, { key: DailyRollupKey; value: DailyRollupValue }>
rollups: Map<string, { key: DailyRollupKey; value: DailyRollupValue }>,
startMs: number,
now: Date
): Promise<boolean> {
try {
const cachedData = await this.deps.getSessionFileDataCached!(sessionFile, fileMtimeMs);
Expand All @@ -192,39 +200,123 @@ export class SyncService {
return false;
}

// Expand cached modelUsage into rollups
const dayKey = this.utility.toUtcDayKey(new Date(fileMtimeMs));
// Parse the session file to get actual request timestamps and create per-day rollups
// This ensures accurate day assignment while using cached token counts
const content = await fs.promises.readFile(sessionFile, 'utf8');

// CRITICAL FIX: Only assign interactions to first model to prevent inflation
// When a file has multiple models, interactions should be counted once, not per-model
let interactionsAssigned = false;
// Map to track per-day per-model interactions for proper distribution
const dayModelInteractions = new Map<string, Map<string, number>>();

for (const [model, usage] of Object.entries(cachedData.modelUsage)) {
// Validate usage object structure
if (!usage || typeof usage !== 'object') {
this.deps.warn(`Backend sync: invalid usage object for model ${model} in ${sessionFile}`);
continue;
// Handle JSONL format (Copilot CLI)
if (sessionFile.endsWith('.jsonl')) {
const lines = content.trim().split('\n');
const todayKey = this.utility.toUtcDayKey(now);
let lineCount = 0;
let processedLines = 0;

for (const line of lines) {
lineCount++;
if (!line.trim()) { continue; }
try {
const event = JSON.parse(line);
if (!event || typeof event !== 'object') { continue; }

const normalizedTs = this.utility.normalizeTimestampToMs(event.timestamp);
const eventMs = Number.isFinite(normalizedTs) ? normalizedTs : fileMtimeMs;
if (!eventMs || eventMs < startMs) { continue; }

const dayKey = this.utility.toUtcDayKey(new Date(eventMs));
const model = (event.model || 'gpt-4o').toString();
const isFileFromToday = dayKey === todayKey;
if (isFileFromToday && processedLines < 3) {
this.deps.log(`Backend sync: file ${sessionFile.split(/[/\\]/).pop()} line ${lineCount}: eventMs=${new Date(eventMs).toISOString()}, dayKey=${dayKey}, type=${event.type}`);
processedLines++;
}
if (!Number.isFinite(usage.inputTokens) || usage.inputTokens < 0) {
this.deps.warn(`Backend sync: invalid inputTokens for model ${model} in ${sessionFile}`);
continue;
// Track interaction for this day+model (count all events, not just user.message)
if (!dayModelInteractions.has(dayKey)) {
dayModelInteractions.set(dayKey, new Map());
}
const dayMap = dayModelInteractions.get(dayKey)!;
dayMap.set(model, (dayMap.get(model) || 0) + 1);
} catch {
// skip malformed line
}
}
if (!Number.isFinite(usage.outputTokens) || usage.outputTokens < 0) {
this.deps.warn(`Backend sync: invalid outputTokens for model ${model} in ${sessionFile}`);
continue;
} else {
// Handle JSON format (VS Code Copilot Chat)
try {
const sessionJson = JSON.parse(content);
if (!sessionJson || typeof sessionJson !== 'object') {
return false;
}
const sessionObj = sessionJson as Record<string, unknown>;
const requests = Array.isArray(sessionObj.requests) ? (sessionObj.requests as unknown[]) : [];

for (const request of requests) {
const req = request as ChatRequest;
const normalizedTs = this.utility.normalizeTimestampToMs(
typeof req.timestamp !== 'undefined' ? req.timestamp : (sessionObj.lastMessageDate as unknown)
);
const eventMs = Number.isFinite(normalizedTs) ? normalizedTs : fileMtimeMs;
if (!eventMs || eventMs < startMs) { continue; }

const dayKey = this.utility.toUtcDayKey(new Date(eventMs));
const model = this.deps.getModelFromRequest(req);


// Track interaction for this day+model
if (!dayModelInteractions.has(dayKey)) {
dayModelInteractions.set(dayKey, new Map());
}
const dayMap = dayModelInteractions.get(dayKey)!;
dayMap.set(model, (dayMap.get(model) || 0) + 1);
}
} catch (e) {
this.deps.warn(`Backend sync: failed to parse JSON for ${sessionFile}: ${e}`);
return false;
}

const key: DailyRollupKey = { day: dayKey, model, workspaceId, machineId, userId };
// Only assign interactions to the first valid model to prevent inflation
const interactionsForThisModel = interactionsAssigned ? 0 : cachedData.interactions;
interactionsAssigned = true;

upsertDailyRollup(rollups, key, {
inputTokens: usage.inputTokens,
outputTokens: usage.outputTokens,
interactions: interactionsForThisModel
});
}

// Now distribute cached token counts proportionally across day+model combinations
// based on the actual interaction distribution we just calculated
for (const [dayKey, modelMap] of dayModelInteractions) {
for (const [model, interactions] of modelMap) {
const cachedUsage = cachedData.modelUsage[model];
if (!cachedUsage) { continue; }

// Validate usage object structure
if (!Number.isFinite(cachedUsage.inputTokens) || cachedUsage.inputTokens < 0) {
this.deps.warn(`Backend sync: invalid inputTokens for model ${model}`);
continue;
}
if (!Number.isFinite(cachedUsage.outputTokens) || cachedUsage.outputTokens < 0) {
this.deps.warn(`Backend sync: invalid outputTokens for model ${model}`);
continue;
}

const key: DailyRollupKey = { day: dayKey, model, workspaceId, machineId, userId };

// For simplicity, if a file spans multiple days, distribute tokens proportionally
// In practice, most session files are from a single day, so this is accurate
const totalInteractionsForModel = Array.from(dayModelInteractions.values())
.reduce((sum, m) => sum + (m.get(model) || 0), 0);

const tokenRatio = totalInteractionsForModel > 0 ? interactions / totalInteractionsForModel : 1;

upsertDailyRollup(rollups, key, {
inputTokens: Math.round(cachedUsage.inputTokens * tokenRatio),
outputTokens: Math.round(cachedUsage.outputTokens * tokenRatio),
interactions: interactions
});
}
}

// Log if this file had data for multiple days (for debugging)
if (dayModelInteractions.size > 1) {
const days = Array.from(dayModelInteractions.keys()).sort();
this.deps.log(`Backend sync: file ${sessionFile.split(/[/\\]/).pop()} spans ${days.length} days: ${days.join(', ')}`);
}

return true;
} catch (e) {
// Differentiate between cache miss (expected) and errors (unexpected)
Expand Down Expand Up @@ -308,6 +400,11 @@ export class SyncService {
start.setUTCHours(0, 0, 0, 0);
start.setUTCDate(start.getUTCDate() - (lookbackDays - 1));
const startMs = start.getTime();

// Log the date range being processed
const todayKey = this.utility.toUtcDayKey(now);
const startKey = this.utility.toUtcDayKey(start);
this.deps.log(`Backend sync: processing sessions from ${startKey} to ${todayKey} (lookback ${lookbackDays} days)`);

const machineId = vscode.env.machineId;
const rollups = new Map<string, { key: DailyRollupKey; value: DailyRollupValue }>();
Expand All @@ -322,6 +419,10 @@ export class SyncService {
const useCachedData = !!this.deps.getSessionFileDataCached;
let cacheHits = 0;
let cacheMisses = 0;
let filesSkipped = 0;
let filesProcessed = 0;

this.deps.log(`Backend sync: analyzing ${sessionFiles.length} session files`);

for (const sessionFile of sessionFiles) {
let fileMtimeMs: number | undefined;
Expand All @@ -330,10 +431,13 @@ export class SyncService {
const fileStat = await fs.promises.stat(sessionFile);
fileMtimeMs = fileStat.mtimeMs;


// Skip files older than lookback period
if (fileMtimeMs < startMs) {
filesSkipped++;
continue;
}
filesProcessed++;
} catch (e) {
this.deps.warn(`Backend sync: failed to stat session file ${sessionFile}: ${e}`);
continue;
Expand All @@ -342,15 +446,19 @@ export class SyncService {
const workspaceId = this.utility.extractWorkspaceIdFromSessionPath(sessionFile);
await this.ensureWorkspaceNameResolved(workspaceId, sessionFile, workspaceNamesById);

// Try to use cached data first (much faster than parsing)
// Try to use cached data first (faster than full recomputation)
// Note: We still parse the file to get accurate day keys from timestamps,
// but use cached token counts for performance
if (useCachedData) {
const cacheSuccess = await this.processCachedSessionFile(
sessionFile,
fileMtimeMs,
workspaceId,
machineId,
userId,
rollups
rollups,
startMs,
now
);

if (cacheSuccess) {
Expand Down Expand Up @@ -474,6 +582,8 @@ export class SyncService {
if (useCachedData) {
this.logCachePerformance(cacheHits, cacheMisses);
}

this.deps.log(`Backend sync: processed ${filesProcessed} files, skipped ${filesSkipped} files outside lookback period`);

return { rollups, workspaceNamesById, machineNamesById };
}
Expand Down Expand Up @@ -502,6 +612,8 @@ export class SyncService {
// Avoid excessive syncing when UI refreshes frequently.
const lastSyncAt = this.deps.context?.globalState.get<number>('backend.lastSyncAt');
if (!force && lastSyncAt && Date.now() - lastSyncAt < BACKEND_SYNC_MIN_INTERVAL_MS) {
const secondsSinceLastSync = Math.round((Date.now() - lastSyncAt) / 1000);
this.deps.log(`Backend sync: skipping (last sync was ${secondsSinceLastSync}s ago, minimum interval is ${BACKEND_SYNC_MIN_INTERVAL_MS / 1000}s)`);
return;
}

Expand All @@ -518,6 +630,17 @@ export class SyncService {

const resolvedIdentity = await this.resolveEffectiveUserIdentityForSync(settings, sharingPolicy.includeUserDimension);
const { rollups, workspaceNamesById, machineNamesById } = await this.computeDailyRollupsFromLocalSessions({ lookbackDays: settings.lookbackDays, userId: resolvedIdentity.userId });

// Log day keys being synced for better visibility
const dayKeys = new Set<string>();
for (const { key } of rollups.values()) {
dayKeys.add(key.day);
}
const sortedDays = Array.from(dayKeys).sort();
if (sortedDays.length > 0) {
this.deps.log(`Backend sync: processing data for ${sortedDays.length} days: ${sortedDays.join(', ')}`);
}

this.deps.log(`Backend sync: upserting ${rollups.size} rollup entities (lookback ${settings.lookbackDays} days)`);

const tableClient = this.dataPlaneService.createTableClient(settings, creds.tableCredential);
Expand Down Expand Up @@ -570,6 +693,13 @@ export class SyncService {
}

this.deps.log('Backend sync: completed');

// Trigger UI refresh to update status bar and panels with latest sync data
try {
await this.deps.updateTokenStats?.();
} catch (e) {
this.deps.warn(`Backend sync: failed to update UI: ${e}`);
}
} catch (e: any) {
// Keep local mode functional.
const secretsToRedact = await this.credentialService.getBackendSecretsToRedactForError(settings);
Expand Down
Loading
Loading